[Solved] ESOCKETTIMEDOUT errors

Troubleshooting
1

All, I have been happily using the WebSockets feature for some time now and I have one issue which I need help tracking down. I have seven devices which are programmed to connect at the top of the hour and report data to Ubidots. I use the device ID in the name of the WebHook and subscription so there does not seem to be any issue with keeping the hooks and responses straight.

char responseTopic[125];
  String deviceID = System.deviceID();
  deviceID.toCharArray(responseTopic,125);
  Particle.subscribe(responseTopic, UbidotsHandler, MY_DEVICES);      // Subscribe to the integration response event

I have read other posts about this issue and heard there is a 5 second timeout for a response from the web service (in my case Ubidots). I asked @aguspg about this and he looked up the Pingdom monitoring from this timeframe and their max response time was 1.19 seconds.

Here are the functions that call and subscribe to the web hook:

void sendEvent()
{
  char data[256];                                         // Store the date in this character array - not global
  snprintf(data, sizeof(data), "{\"hourly\":%i, \"daily\":%i,\"battery\":%i, \"temp\":%i, \"resets\":%i}",hourlyPersonCount, dailyPersonCount, stateOfCharge, temperatureF,resetCount);
  Particle.publish("Ubidots-Hook", data, PRIVATE);
  hourlyPersonCountSent = hourlyPersonCount; // This is the number that was sent to Ubidots - will be subtracted once we get confirmation
  currentHourlyPeriod = Time.hour();  // Change the time period
  dataInFlight = true; // set the data inflight flag
}

void UbidotsHandler(const char *event, const char *data)  // Looks at the response from Ubidots - Will reset Photon if no successful response
{
  // Response Template: "{{hourly.0.status_code}}"
  if (!data) {                                            // First check to see if there is any data
    Particle.publish("Ubidots Hook", "No Data");
    return;
  }
  int responseCode = atoi(data);                          // Response is only a single number thanks to Template
  if ((responseCode == 200) || (responseCode == 201))
  {
    Particle.publish("State","Response Received");
    dataInFlight = false;                                 // Data has been received
  }
  else Particle.publish("Ubidots Hook", data);             // Publish the response code
}

So, here is my question. If I am not getting ESOCKETTIMEDOUT from a slow response, could it be from multiple Electrons using the same Webhook at the same time? Is there a limit here which might require me to either create more web hooks or stagger the top-of-the-hour reporting?

Why this matters: When the web hook is sent, and there is an ESOCKETTTIMEDOUT, it is resent. Ubidots had received the first and second hooks and creates two data entries as you can see below. I would like to eliminate this duplicative data.

Screen Shot 2017-11-02 at 6.18.39 PM.png1316×685 78.6 KB

I am providing the screen shots from the activity log and the console output if there is more to the story in the data. Please let me know if you need to see more.

Screen Shot 2017-11-02 at 6.06.19 PM.png1426×275 33 KB
Screen Shot 2017-11-02 at 6.01.01 PM.png1343×610 73.8 KB
Screen Shot 2017-11-02 at 6.00.20 PM.png1329×696 87.6 KB 

event: Ubidots-Hook
data: {"data":"{\"hourly\":91, \"daily\":934,\"battery\":82, \"temp\":75, \"resets\":0}","ttl":60,"published_at":"2017-11-02T21:59:36.468Z","coreid":"4f0031000251353337353037"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T21:59:36.495Z","coreid":"particle-internal"}

event: 4f0031000251353337353037_Ubidots-Hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T21:59:37.373Z","coreid":"particle-internal"}

event: Ubidots
data: {"data":"Success","ttl":60,"published_at":"2017-11-02T21:59:38.093Z","coreid":"4f0031000251353337353037"}

event: weatherU_hook
data: {"data":"null","ttl":60,"published_at":"2017-11-02T22:00:00.942Z","coreid":"37003e001447343339383037"}

event: hook-sent/weatherU_hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:00.990Z","coreid":"particle-internal"}

event: hook-response/weatherU_hook/0
data: {"data":"2~0~3~0~4~0~5~0~","ttl":60,"published_at":"2017-11-02T22:00:01.227Z","coreid":"particle-internal"}

event: AquaMaster_hook
data: {"data":"{\"Moisture\":494, \"Watering\":0, \"key1\":\"Not Time\", \"SoilTemp\":21}","ttl":60,"published_at":"2017-11-02T22:00:01.348Z","coreid":"37003e001447343339383037"}

event: hook-sent/AquaMaster_hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:01.384Z","coreid":"particle-internal"}

event: Ubidots-Hook
data: {"data":"{\"hourly\":11, \"daily\":66,\"battery\":79, \"temp\":71, \"resets\":0}","ttl":60,"published_at":"2017-11-02T22:00:01.602Z","coreid":"30005d001851353338363036"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:01.679Z","coreid":"particle-internal"}

event: Ubidots-Hook
data: {"data":"{\"hourly\":87, \"daily\":747,\"battery\":79, \"temp\":77, \"resets\":0}","ttl":60,"published_at":"2017-11-02T22:00:03.246Z","coreid":"4a003a000251363131363432"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:03.334Z","coreid":"particle-internal"}

event: Ubidots-Hook
data: {"data":"{\"hourly\":27, \"daily\":130,\"battery\":78, \"temp\":73, \"resets\":0}","ttl":60,"published_at":"2017-11-02T22:00:04.167Z","coreid":"550035000251363131363432"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:04.377Z","coreid":"particle-internal"}

event: 550035000251363131363432_Ubidots-Hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T22:00:04.901Z","coreid":"particle-internal"}

event: UbidotsHook
data: {"data":"Success","ttl":60,"published_at":"2017-11-02T22:00:05.631Z","coreid":"550035000251363131363432"}

event: hook-error/AquaMaster_hook/0
data: {"data":"ESOCKETTIMEDOUT","ttl":60,"published_at":"2017-11-02T22:00:06.601Z","coreid":"particle-internal"}

event: hook-error/Ubidots-Hook/0
data: {"data":"ESOCKETTIMEDOUT","ttl":60,"published_at":"2017-11-02T22:00:06.893Z","coreid":"particle-internal"}

event: hook-error/Ubidots-Hook/0
data: {"data":"ESOCKETTIMEDOUT","ttl":60,"published_at":"2017-11-02T22:00:08.537Z","coreid":"particle-internal"}

event: hook-sent/AquaMaster_hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:31.379Z","coreid":"particle-internal"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:31.648Z","coreid":"particle-internal"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:33.280Z","coreid":"particle-internal"}

event: 37003e001447343339383037_AquaMaster_hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T22:00:33.332Z","coreid":"particle-internal"}

event: AquaMaster
data: {"data":"Success","ttl":60,"published_at":"2017-11-02T22:00:33.466Z","coreid":"37003e001447343339383037"}

event: 30005d001851353338363036_Ubidots-Hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T22:00:34.413Z","coreid":"particle-internal"}

event: UbidotsHook
data: {"data":"Success","ttl":60,"published_at":"2017-11-02T22:00:36.381Z","coreid":"30005d001851353338363036"}

event: 4a003a000251363131363432_Ubidots-Hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T22:00:37.223Z","coreid":"particle-internal"}

event: Ubidots
data: {"data":"Success","ttl":60,"published_at":"2017-11-02T22:00:40.770Z","coreid":"4a003a000251363131363432"}

event: spark/status
data: {"data":"online","ttl":60,"published_at":"2017-11-02T22:00:49.217Z","coreid":"340040000251363131363432"}

event: Ubidots-Hook
data: {"data":"{\"hourly\":47, \"daily\":357,\"battery\":83, \"temp\":68, \"resets\":1}","ttl":60,"published_at":"2017-11-02T22:00:50.657Z","coreid":"340040000251363131363432"}

event: hook-sent/Ubidots-Hook
data: {"data":"","ttl":60,"published_at":"2017-11-02T22:00:50.695Z","coreid":"particle-internal"}

event: State
data: {"data":"Waiting for Response","ttl":60,"published_at":"2017-11-02T22:00:50.926Z","coreid":"340040000251363131363432"}

event: 340040000251363131363432_Ubidots-Hook/0
data: {"data":"201","ttl":60,"published_at":"2017-11-02T22:00:51.334Z","coreid":"particle-internal"}

event: State
data: {"data":"Response Received","ttl":60,"published_at":"2017-11-02T22:00:52.198Z","coreid":"340040000251363131363432"}

event: State
data: {"data":"Idle","ttl":60,"published_at":"2017-11-02T22:00:52.656Z","coreid":"340040000251363131363432"}

event: State
data: {"data":"Counting","ttl":60,"published_at":"2017-11-02T22:01:09.198Z","coreid":"340040000251363131363432"}

Thanks,

Chip

2

Did you check rate-limiting to see if you are getting a 429 response when you try to generate 7 (nearly simultaneous) requests?

3

@BulldogLowell,

I do check the response codes from Ubidots and don’t see any response when there is a ESCOKETTIMEDOUT error.

From what I can see (and I will show what today’s log looked like), Particle is sending the data to Ubidots but not getting any response (or too many simultaneous responses?) but nothing is passed back to my response handler (code provided above). Then, Particle retries the Webhook up to 5 times, each time, Ubidots records a new datapoint so, the hook is getting through. This is generating extra network traffic and redundant data points. This is a minor pain now but, what happens if I have 100 or more of these devices deployed?

Screen Shot 2017-11-06 at 7.04.49 AM.png1030×272 15.1 KB
Screen Shot 2017-11-06 at 7.02.00 AM.png1413×849 120 KB

Thanks,

Chip

4

if you are not concerned about every device updating at the top of the hour, you could hash the last byte of the DeviceID into a number from 0-59 and use that as the minute to TX. Basically, let each happen over a more distributed minute of the hour but not have to hardcode each device...

5

@BulldogLowell,

That would be a good solution but this is part of a reporting system for our local parks. They want to look at this data and ask, how many visitors came to the park over their lunch hour? or, if I close the park at 7pm instead of 8pm, what would be the impact? These questions are more neatly answered when all the sensors around the park report at the same time.

Besides, if I can’t solve this issue now with a single park, randomizing the reporting will only kick the problem down the road. At some point as the number of devices grows, there will be several in flight at one time. Given the nature of scaling over the Internet. I am a bit surprised to be overwhelming the system with only a handful of drives - right?

Chip

6

given the access to an api from virtually anywhere, I'm not surprised that rate limiting is necessary!

you could use the above and bracket the data within meaningful buckets inside a JSON.

{"guests": [{"11:15": 23},{"11:30": 28},{"11:45":35},{"12:00":49}]}

or just:

{"guests": {"12:00":49}}  //this was the count at the hour ending at noon

and handle that data server-side accordingly.

7

Ubidots seems to periodically have these moments, on the free platform in particular and to me that screenshot looks like Ubidots is where the issue lies.
You can send your data with a timestamp in the context if that helps…
With my project, to reduce the number of particle events and (Ubi)dots I group together data into arrays with timestamps and then send those and I only send other data when it has changed.
If you are not already using the commercial Ubidots platform it is worth trying as there are also features you discover when talking to them that they enable on a per account basis and others in development. It is also worth mentioning that Losant also plays quite well with Particle and because it can hook directly into the Particle event stream, no need for webhooks. It is quite a bit more involved than Ubidots however, at least to get started.

1 Like
8

@Viscacha,

Thank you for taking a look. I have had this issue on both the free and commercial Ubidots platform. I am on the commercial platform now. Ubidots brings some other important elements to the solution so, I want to see if I can make this work reliably.

Thanks,

Chip

9

All,

In talking with the good folks at Ubidots and sharing this data, this issue has been resolved. Ubidots made some changes to how quickly they respond and I moved to their industrial service. These changes have made a dramatic improvement where I am seeing few or - as the attached imaged shows - no timeouts.

I guess the lessons here are:

  • Make sure you respect Particle’s publish rate limits (1 per second on average and no more than 4 in a second burst)
  • Write your code to subscribe to a response but allow for retries if there is a ESOCKETTIMEDOUT error
  • Work with your service provided and provide them with the information needed to diagnose the issue.

Thank you to @aguspg for helping me work through this - it is this service that endears me to Ubidots.

Chip

Screen Shot 2017-11-09 at 11.13.08 AM.png1426×946 134 KB

1 Like