inwaar/node-red-contrib-fibaro-hc2-bridge

Error: ESOCKETTIMEDOUT

osvedman opened this issue · 8 comments

osvedman commented

The node is getting data from HC2, but several times every minute, it returns this error message:

Error: ESOCKETTIMEDOUT

And I think it causes me to lose events sent when it happens. One of my uses for this node is to track power usage, and Node-RED will often have a different last value than the actual HC2 does.

image

inwaar commented

Hi osvedman, could you provide the following information:

  1. what the device you run NodeRED on
  2. what the operation system is used for the device running NodeRED
  3. what is the network setup, is it WiFi or LAN
  4. do you have any lost packets if you ping your HomeCenter?
  5. what is the version of HomeCentrer
  6. what is the version of NodeRED
  7. what is the version of NodeJS
  • 👍1
osvedman commented
  1. Raspberry Pi 4, 4 GB
  2. Raspian, packages and nodes updated a few days ago
  3. Wifi
  4. 127 packets transmitted, 127 received, 0% packet loss, time 311ms
    rtt min/avg/max/mdev = 1.072/3.900/102.134/12.003 ms
  5. 4.580, but I also had this issue with versions before this
  6. 1.0.5, but I also had this issue with 1.0.4
  7. 12.16.1
inwaar commented

  1. Is there any possibility you try temporarily to use Ethernet connection instead of WiFi to check if that's not the issue?

  2. Turn on debug logging:
    image

And check logs on your Raspberry Pi:

sudo journalctl -f

Do you see anything weird in the logs when you get mentioned errors in NodeRED debug window?

osvedman commented

I'll check if I can try Ethernet, but it's not easy for me. I'll post back later, unless you get any more info from the log below.

Enabling Debug on the HC2 node didn't seem to introduce any new logging, at least not to the Debug node.

Here are some of the Raspberry Pi log during the errors:

Apr 14 21:41:27 raspberrypi Node-RED[18941]: 0.3689828181214361: query [ 'http://192.168.1.87/api/refreshStates?last=463849&lang=en' ]
Apr 14 21:41:28 raspberrypi Node-RED[18941]: Idle
Apr 14 21:41:34 raspberrypi Node-RED[18941]: 0.3689828181214361: query: error [
Apr 14 21:41:34 raspberrypi Node-RED[18941]: Error: ESOCKETTIMEDOUT
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at ClientRequest. (/home/pi/.node-red/node_modules/request/request.js:816:19)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at Object.onceWrapper (events.js:417:28)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at ClientRequest.emit (events.js:311:20)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at Socket.emitRequestTimeout (_http_client.js:714:9)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at Object.onceWrapper (events.js:417:28)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at Socket.emit (events.js:311:20)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at Socket._onTimeout (net.js:478:8)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at listOnTimeout (internal/timers.js:549:17)
Apr 14 21:41:34 raspberrypi Node-RED[18941]: at processTimers (internal/timers.js:492:7) {
Apr 14 21:41:34 raspberrypi Node-RED[18941]: code: 'ESOCKETTIMEDOUT',
Apr 14 21:41:34 raspberrypi Node-RED[18941]: connect: false
Apr 14 21:41:34 raspberrypi Node-RED[18941]: }
Apr 14 21:41:34 raspberrypi Node-RED[18941]: ]
Apr 14 21:41:48 raspberrypi Node-RED[18941]: 0.3689828181214361: query: error [
Apr 14 21:41:48 raspberrypi Node-RED[18941]: Error: ESOCKETTIMEDOUT
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at ClientRequest. (/home/pi/.node-red/node_modules/request/request.js:816:19)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at Object.onceWrapper (events.js:417:28)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at ClientRequest.emit (events.js:311:20)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at Socket.emitRequestTimeout (_http_client.js:714:9)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at Object.onceWrapper (events.js:417:28)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at Socket.emit (events.js:311:20)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at Socket._onTimeout (net.js:478:8)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at listOnTimeout (internal/timers.js:549:17)
Apr 14 21:41:48 raspberrypi Node-RED[18941]: at processTimers (internal/timers.js:492:7) {
Apr 14 21:41:48 raspberrypi Node-RED[18941]: code: 'ESOCKETTIMEDOUT',
Apr 14 21:41:48 raspberrypi Node-RED[18941]: connect: false
Apr 14 21:41:48 raspberrypi Node-RED[18941]: }
Apr 14 21:41:48 raspberrypi Node-RED[18941]: ]
Apr 14 21:41:55 raspberrypi Node-RED[18941]: 0.3689828181214361: query: event.response.statusCode [ 200 ]
Apr 14 21:41:55 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: events [ 0 ]
Apr 14 21:41:55 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: device events [ 0 ]
Apr 14 21:41:56 raspberrypi Node-RED[18941]: 0.3689828181214361: query [ 'http://192.168.1.87/api/refreshStates?last=463855&lang=en' ]
Apr 14 21:41:57 raspberrypi Node-RED[18941]: Idle
Apr 14 21:41:59 raspberrypi Node-RED[18941]: 0.3689828181214361: query: event.response.statusCode [ 200 ]
Apr 14 21:41:59 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: events [ 0 ]
Apr 14 21:41:59 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: device events [ 0 ]
Apr 14 21:42:00 raspberrypi Node-RED[18941]: 0.3689828181214361: query [ 'http://192.168.1.87/api/refreshStates?last=463858&lang=en' ]
Apr 14 21:42:02 raspberrypi Node-RED[18941]: 0.3689828181214361: query: event.response.statusCode [ 200 ]
Apr 14 21:42:02 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: events [ 1 ]
Apr 14 21:42:02 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: device events [ 0 ]
Apr 14 21:42:03 raspberrypi Node-RED[18941]: 0.3689828181214361: query [ 'http://192.168.1.87/api/refreshStates?last=463860&lang=en' ]
Apr 14 21:42:03 raspberrypi Node-RED[18941]: 0.3689828181214361: query: event.response.statusCode [ 200 ]
Apr 14 21:42:03 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: events [ 1 ]
Apr 14 21:42:03 raspberrypi Node-RED[18941]: 0.3689828181214361: _events: device events [ 0 ]
Apr 14 21:42:04 raspberrypi Node-RED[18941]: 0.3689828181214361: query [ 'http://192.168.1.87/api/refreshStates?last=463861&lang=en' ]

inwaar commented

Ok, this is probably has nothing to WiFi.

If you login to your HC in Google Chrome and open the debug tool (F12), check what is the average and the maximum response time for the refreshStates requests:

image

I suspect you have not many devices connected to HC and as a result less events and HC increases timeouts to push data to clients. Currently the node has timeout of 7 seconds.

If this is the case I could make the timeout configurable in the node UI so that you could increase it or I'm considering even increasing it by default.

osvedman commented

That is probably it! When looking at it only briefly, I saw that there were at least one occasion with 21 seconds between refreshes. Doesn't explain why the power reading on my Node-RED doesn't match the one on the HC2, but it seems to explain the error message from your node.

Btw: Number of devices: 28. Recommended devices polling time interval: 300s.

inwaar commented

I've released a new version 0.2.0 where the timeout increased to 30s instead of 7s and it's also configurable now.

image

The node update will be available in a short while in your NodeRED palette.
Let me know what timeout value is fixing your issue.

  • ❤️1
osvedman commented

Amazing, thank you very much!