aarons22 / homebridge-bond

Homebridge plugin for Bond
MIT License
63 stars 31 forks source link

Error: "timeout of 10000ms exceeded" #201

Open UncleJerm76 opened 2 years ago

UncleJerm76 commented 2 years ago

I have 6 ceiling fans controlled by Bond. I am getting what appears to me as random timeout errors. Sometimes a bond fan will start properly, other times it will timeout. I feel like this started happening right after the last Bond firmware update - but I have no proof of that.

However, I will add a few things: If left alone the errors cause the Fans to show up as "Unreachable" in iOS Home. But if I keep rebooting Homebridge, the Bond errors eventually go away - all of them, I see fewer errors with every continued reboot until finally the Bond plugin does a clean start. At this point all fans work... until they dont. I also noticed if I leave it for some time and come back and do another reboot the errors all come back and I have to continue the process described above.

+-- homebridge-bond@3.2.9 HomeBridge UI Bond Firmware 2.28.0

Log of my most recent error below showing some fans loaded while others timed out: [2/5/2022, 9:38:23 AM] [homebridge-bond] 5 cached accessories were loaded [2/5/2022, 9:38:23 AM] [homebridge-bond] Getting devices for this Bond (ZZDJ48976)... [2/5/2022, 9:38:23 AM] [homebridge-bond] 6 devices were found on this Bond (ZZDJ48976). [2/5/2022, 9:38:23 AM] [homebridge-bond] Attempting to add 1 devices that were not previously added. [2/5/2022, 9:38:23 AM] [homebridge-bond] Configuring Accessory: Nook Nook Ceiling Fan [2/5/2022, 9:38:23 AM] [homebridge-bond] [Nook Ceiling Fan] actions: TurnOff,SetSpeed,SetDirection,StartDecreasingBrightness,ToggleLight,StartIncreasingBrightness,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:23 AM] [homebridge-bond] Configuring Accessory: Living Room Living Room Ceiling Fan [2/5/2022, 9:38:23 AM] [homebridge-bond] [Living Room Ceiling Fan] actions: SetSpeed,StartIncreasingBrightness,StartDecreasingBrightness,ToggleLight,TurnOff,SetDirection,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:23 AM] [homebridge-bond] Configuring Accessory: Kids Room KR1 Ceiling Fan [2/5/2022, 9:38:23 AM] [homebridge-bond] [KR1 Ceiling Fan] actions: SetSpeed,SetDirection,StartDecreasingBrightness,TurnOff,ToggleLight,StartIncreasingBrightness,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:23 AM] [homebridge-bond] Configuring Accessory: Master Bedroom Master Ceiling Fan [2/5/2022, 9:38:23 AM] [homebridge-bond] [Master Ceiling Fan] actions: StartIncreasingBrightness,SetDirection,StartDecreasingBrightness,SetSpeed,ToggleLight,TurnOff,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:23 AM] [homebridge-bond] Configuring Accessory: Kids Room KR2 Ceiling Fan [2/5/2022, 9:38:23 AM] [homebridge-bond] [KR2 Ceiling Fan] actions: SetDirection,StartDecreasingBrightness,SetSpeed,StartIncreasingBrightness,TurnOff,ToggleLight,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:33 AM] [homebridge-bond] A request error occurred: {"message":"timeout of 10000ms exceeded","name":"Error","stack":"Error: timeout of 10000ms exceeded\n at createError (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/core/createError.js:16:15)\n at RedirectableRequest.handleRequestTimeout (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/adapters/http.js:303:16)\n at RedirectableRequest.emit (node:events:390:28)\n at Timeout. (/homebridge/node_modules/homebridge-bond/node_modules/follow-redirects/index.js:164:12)\n at listOnTimeout (node:internal/timers:557:17)\n at processTimers (node:internal/timers:500:7)","config":{"url":"http://192.168.7.29/v2/devices/6b2b0fbf/commands/4b476173","method":"get","data":"{}","headers":{"Accept":"application/json, text/plain, /","BOND-Token":"55191f48b032ac28","Bond-UUID":"185fb29498928002","Content-Type":"application/json","User-Agent":"axios/0.21.4","Content-Length":2},"transformRequest":[null],"transformResponse":[null],"timeout":10000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false},"axios-retry":{"retryCount":0,"lastRequestTime":1644071903819}},"code":"ECONNABORTED"} [2/5/2022, 9:38:33 AM] [homebridge-bond] A request error occurred: {"message":"timeout of 10000ms exceeded","name":"Error","stack":"Error: timeout of 10000ms exceeded\n at createError (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/core/createError.js:16:15)\n at RedirectableRequest.handleRequestTimeout (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/adapters/http.js:303:16)\n at RedirectableRequest.emit (node:events:390:28)\n at Timeout. (/homebridge/node_modules/homebridge-bond/node_modules/follow-redirects/index.js:164:12)\n at listOnTimeout (node:internal/timers:557:17)\n at processTimers (node:internal/timers:500:7)","config":{"url":"http://192.168.7.29/v2/devices/6b2b0fbf/commands/2119b3fb","method":"get","data":"{}","headers":{"Accept":"application/json, text/plain, /","BOND-Token":"55191f48b032ac28","Bond-UUID":"185fb29498928003","Content-Type":"application/json","User-Agent":"axios/0.21.4","Content-Length":2},"transformRequest":[null],"transformResponse":[null],"timeout":10000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false},"axios-retry":{"retryCount":0,"lastRequestTime":1644071903819}},"code":"ECONNABORTED"} [2/5/2022, 9:38:33 AM] [homebridge-bond] A request error occurred: {"message":"timeout of 10000ms exceeded","name":"Error","stack":"Error: timeout of 10000ms exceeded\n at createError (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/core/createError.js:16:15)\n at RedirectableRequest.handleRequestTimeout (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/adapters/http.js:303:16)\n at RedirectableRequest.emit (node:events:390:28)\n at Timeout. (/homebridge/node_modules/homebridge-bond/node_modules/follow-redirects/index.js:164:12)\n at listOnTimeout (node:internal/timers:557:17)\n at processTimers (node:internal/timers:500:7)","config":{"url":"http://192.168.7.29/v2/devices/6b2b0fbf/commands/1a21cf44","method":"get","data":"{}","headers":{"Accept":"application/json, text/plain, /","BOND-Token":"55191f48b032ac28","Bond-UUID":"185fb29498928004","Content-Type":"application/json","User-Agent":"axios/0.21.4","Content-Length":2},"transformRequest":[null],"transformResponse":[null],"timeout":10000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false},"axios-retry":{"retryCount":0,"lastRequestTime":1644071903819}},"code":"ECONNABORTED"} [2/5/2022, 9:38:33 AM] [homebridge-bond] A request error occurred: {"message":"timeout of 10000ms exceeded","name":"Error","stack":"Error: timeout of 10000ms exceeded\n at createError (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/core/createError.js:16:15)\n at RedirectableRequest.handleRequestTimeout (/homebridge/node_modules/homebridge-bond/node_modules/axios/lib/adapters/http.js:303:16)\n at RedirectableRequest.emit (node:events:390:28)\n at Timeout. (/homebridge/node_modules/homebridge-bond/node_modules/follow-redirects/index.js:164:12)\n at listOnTimeout (node:internal/timers:557:17)\n at processTimers (node:internal/timers:500:7)","config":{"url":"http://192.168.7.29/v2/devices/6b2b0fbf/commands/7161f811","method":"get","data":"{}","headers":{"Accept":"application/json, text/plain, /","BOND-Token":"55191f48b032ac28","Bond-UUID":"185fb29498928005","Content-Type":"application/json","User-Agent":"axios/0.21.4","Content-Length":2},"transformRequest":[null],"transformResponse":[null],"timeout":10000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false},"axios-retry":{"retryCount":0,"lastRequestTime":1644071903819}},"code":"ECONNABORTED"} [2/5/2022, 9:38:33 AM] [homebridge-bond] [Office Ceiling fan] actions: OEMTimer,SetSpeed,StartDecreasingBrightness,SetDirection,OEMRandom,StartIncreasingBrightness,ToggleLight,TurnOff,Stop,TogglePower,TurnOn,IncreaseSpeed,DecreaseSpeed,ToggleDirection,TurnLightOn,TurnLightOff [2/5/2022, 9:38:33 AM] [homebridge-bond] Error getting devices: TypeError: Cannot read properties of undefined (reading 'action')

tainted8 commented 2 years ago

I was constantly getting this error and was never able to get my 4 fans to load. I was finally able to figure out tonight that if I remove the 4 timer settins from my Bond app for each device i was finally able to get them to load properly without getting this error. The timers i removed were "Timer 2h", "Timer 4h", "Timer 8h", and "Timer Off".

rcbn commented 2 years ago

This is a problem for me as well. I tried removing the timers but still no luck.

UncleJerm76 commented 1 year ago

Just thought Id pop in here to say I'm still having this issue. My newest issue is no matter how many times I restart HB the errors do not go away any more. So as of right now I'm stuck with only 2 of my 6 fans working through HomeBridge. Hope it gets fixed soon.

@tainted8 BTW, I have no timers on any of my fans in Bond so removing the timers definitely do-not fix it. Sigh. BondError

dafrautn commented 1 year ago

@UncleJerm76 I am having the same issue as you. I'm not sure why I started getting timeout errors, but I managed to workaround the issue by changing the timeout value. I am running the Hyper-V iso image on my Windows 10 system. Within the Ubuntu image, I modified the following file: /var/lib/homebridge/node_modules/homebridge-bond/dist/BondApi.js and change the following line of code:

    return axios({
      method,
      url: uri,
      headers: {
        'BOND-Token': this.bondToken,
        'Bond-UUID': bondUuid,
      },
      data: body,
      timeout: 60000, //Change this from 10000 -> 60000
    })

This change will obviously get wiped-out if I update the plugin, but should hopefully get you around this issue for now.

mbhforum commented 1 year ago

I am having this issue with my Bond Pro. Ironically, the official Homekit integration with Bond results in devices constantly showing "No Response" and is a known issue. I figured I would try this and my devices won't even get imported due to these timeouts. I do not see any sort of timer setting within my devices. Also - I am using docker. so cannot find BondApi.js anywhere. Any help is appreciated.

zakrocki commented 1 year ago

Same issue here with a Bond Pro getting the dreaded "timeout of 10000ms exceeded" error and no devices importing. :(

dacarson commented 1 year ago

I too am seeing this issue. I only started seeing this issue when I switched from a Bond to a Bond Pro, and I enabled their HomeKit integration. I still use this Homebridge plugin as Bond's HomeKit integration only supports Shades, and I also have Fans (with lights) and a fireplace. I have told the homebridge plugin to ignore all the shades.

I wonder if this is happening because Bond can't handle multiple clients (HomeKit directly and Homebridge).

dacarson commented 1 year ago

I did a packet trace, using tcpdump+wireshark, to see if I could work out what was going on. What I noticed was that all of the failed (timed out) requests never hit the network. This makes me suspect that the timeout actually starts when the request is made, not when the request was issued to the Bond device.

dacarson commented 1 year ago

I changed the timeout to be a very high number (1,000,000) as mentioned by dafrautn above https://github.com/aarons22/homebridge-bond/issues/201#issuecomment-1295972955, and then reloaded. I found that it takes approx. 36s (36,000ms) to load all the Bond devices and then load all the commands of each of those devices.

What I think is happening is that it loads the list of devices. As soon as that list returns, it requests for each \<device> it loads the device properties, <device>/properties and device commands <device>/commands. Then it loads the details of each command, <device>/command/<command> and finally the status of each device, <device>/state

The more devices you have, and the mode commands per device, the longer it will take as it queues up a tree of network requests. For me, it would regularly time out while trying to fetch all the command statuses or device state.

IMO, the timeout should be removed, as it is variable depending on the user's setup, and rely on the built in socket timeout mechanism.

searls commented 1 year ago

IMO, the timeout should be removed, as it is variable depending on the user's setup, and rely on the built in socket timeout mechanism.

I agree—the timeout should be configurable or greatly increased. It's pretty clear that for large installations, the tiny bond bridge simply can't keep up when saturated with all of these requests.

searls commented 10 months ago

Just chiming in to say that this still seems to be an issue on the latest version of Bond Pro firmware (v3.19.7-beta) and iOS app (v2.48.0-beta).

I've tried removing all "Other" commands from my fan remotes (including timers), as each individual command does indeed necessitate a round-trip network request at start time. I've also increased the timeout from 10 seconds to 1000 seconds (16 minutes) and that hasn't done anything, either.

After the timeout, 3 or 4 of my 9 fan remotes show up in the Home app but are totally non-responsive (No Response error), but they actually work when interacted with in the Homebridge "Accessories" tab, which is interesting.

searls commented 10 months ago

I just sent #254 as a PR that rate limits how many requests are sent simultaneous to the Bond bridge (on the theory that sending > 5 requests simultaneously was exceeding the number of open sockets it was listening on and just dropping the subsequent requests).

If you want to try this out for yourself I published the fork has homebridge-bond-searls. It's working for me.