search

nicoduj / homebridge-harmony

Harmony websocket plugin for homebridge
The Unlicense
215 stars 23 forks source link

[BUG] #380

Closed Gullwingdmc closed 2 years ago

Gullwingdmc commented 2 years ago

Describe the bug HomeBridge log repeatedly reports "error retrieving info from hub". I have had 3 Harmony hubs setup in HomeBridge for a while now. In the last 2 months they have started throwing this error over and over:

[11/11/2021, 18:41:41] [Living Room] (Living Room)INFO - Loading activities... [11/11/2021, 18:41:52] [Living Room] (Living Room)Error - Error retrieving info from hub : network timeout at: http://192.168.1.217:8088/-(442)

If I restart the Harmony hub it will come back online and the error stops, but then eventually a different hub will start throwing the error. Often then one hub starts having issues it will take the other 2 down with it. I have tried rebuilding the HomeBridge (running on a RasberryPi Zero) several times and re-setting up the plugin with just one hub. No matter what eventually this error shows up. To my knowledge the Harmony hubs have not been changed any time recently. Other plugins on the HomeBridge are running fine. I have tried rolling back to previous versions of the plugin to see if a new version broke something, but no luck.

To Reproduce Reboot and wait a few days.

Expected behavior No errors

Screenshots [11/11/2021, 18:41:41] [Living Room] (Living Room)INFO - Loading activities... [11/11/2021, 18:41:52] [Living Room] (Living Room)Error - Error retrieving info from hub : network timeout at: http://192.168.1.217:8088/-(442)

IOS (please complete the following information):

Logs [11/11/2021, 18:41:41] [Living Room] (Living Room)INFO - Loading activities... [11/11/2021, 18:41:52] [Living Room] (Living Room)Error - Error retrieving info from hub : network timeout at: http://192.168.1.217:8088/-(442)

Config { "name": "Living Room", "hubIP": "192.168.1.217", "hubName": "Living Room", "DELAY_BEFORE_RETRY_AFTER_NETWORK_LOSS": 60000, "HUB_CONNECT_TIMEOUT": 10599, "HUB_SEND_TIMEOUT": 30000, "TVAccessory": true, "mainActivity": "Watch Apple TV", "activitiesToPublishAsInputForTVMode": [ "Watch Apple TV", "Play Xbox", "External Device" ], "publishGeneralVolumeSwitches": true, "linkVolumeControlToTV": true, "devicesToPublishAsAccessoriesSwitch": [ "Apple TV|Button1;Play" ], "platform": "HarmonyHubWebSocket" }

Additional context Add any other context about the problem here.

nicoduj commented 2 years ago

Hi, I nonly see one hub in your conf : how did you add others ? I suggest using otherplatform with only 1 plugin, or using separate homebridge hubs in homebridge, but don't use multiple instance of the plugin on same hub. See if it helps.

Gullwingdmc commented 2 years ago

Hi, I had removed the other hubs while troubleshooting the problem. It still occurred with just one hub setup so I figured I’d leave the others out until I could figure out the issue. I know it’s not this specific harmony hub either, because the others were having the same problem at different times. I would restart 1 harmony hub that was throwing this error and everything would start working again, then a few days later a different one would start to throw the same error.

I can try the otherplatform suggestion. Is that running it as a separate process on the same Pi, or running a completely different Pi?

I had all 3 working fine for months without issue along with other home bridge plugins, then this problem started. We also tried wiping the Pi and setting it up from a backup, but the same errors started after a few days.

Any suggestions would be a huge help. Thank You!!

brummbaer commented 2 years ago

I also have this problem, no matter what I set in the timeouts. Every 10 seconds I get this error message. However, my hub is switched off with the help of a switchable socket. The delays do not work as expected. 

[11/24/2021, 12:14:43 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:14:46 PM] [Heimkino] (Heimkino)Error - Error retrieving info from hub : request to http://192.168.3.87:8088/ failed, reason: connect EHOSTUNREACH 192.168.3.87:8088-(60)
[11/24/2021, 12:14:56 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:14:59 PM] [Heimkino] (Heimkino)Error - Error retrieving info from hub : request to http://192.168.3.87:8088/ failed, reason: connect EHOSTUNREACH 192.168.3.87:8088-(61)
[11/24/2021, 12:15:09 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:15:12 PM] [Heimkino] (Heimkino)Error - Error retrieving info from hub : request to http://192.168.3.87:8088/ failed, reason: connect EHOSTUNREACH 192.168.3.87:8088-(62)

while booting:

[11/24/2021, 12:22:37 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:22:37 PM] [Heimkino] (Heimkino)Error - Error retrieving info from hub : request to http://192.168.3.87:8088/ failed, reason: connect ECONNREFUSED 192.168.3.87:8088-(9)
[11/24/2021, 12:22:47 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:22:47 PM] [Heimkino] (Heimkino)Error - Error retrieving info from hub : request to http://192.168.3.87:8088/ failed, reason: connect ECONNREFUSED 192.168.3.87:8088-(10)

after booting:

[11/24/2021, 12:33:10 PM] [Heimkino] (Heimkino)INFO - Loading activities...
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Adding Accessory : Heimkino-TV
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - configuring Main TV Service
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Creating TV Service
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Creating Input Service - Heimkino Rubin
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Creating Input Service - Heimkino Airplay
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Configuring Main Activity Heimkino Apple TV
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Creating TV Speaker Service
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Creating Input Service - Heimkino Apple TV
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Discovered Activity : Heimkino Rubin
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Discovered Activity : Heimkino Airplay
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - Discovered Activity : Heimkino Apple TV
[11/24/2021, 12:33:11 PM] [Heimkino] (Heimkino)INFO - setupFoundAccessories - TV accessory added as external accessory
[11/24/2021, 12:33:11 PM] Heimkino-TV 0ADB is running on port 41637.
{
            "name": "Heimkino",
            "hubIP": "192.168.3.87",
            "hubName": "Heimkino",
            "DELAY_BEFORE_RETRY_AFTER_NETWORK_LOSS": 100000,
            "HUB_CONNECT_TIMEOUT": 60000,
            "HUB_SEND_TIMEOUT": 30000,
            "TVAccessory": true,
            "configureAccesscontrol": false,
            "mainActivity": "Apple TV",
            "playPauseBehavior": true,
            "numberOfCommandsSentForVolumeControl": 4,
            "switchAccessories": true,
            "publishGeneralVolumeSlider": false,
            "publishGeneralVolumeSwitches": false,
            "linkVolumeControlToTV": false,
            "publishSwitchActivitiesAsIndividualAccessories": false,
            "platform": "HarmonyHubWebSocket"
        },
nicoduj commented 2 years ago

Hi,

Could you check the behavior booting homebridge with the hub online and disconnecting it afterwards ? The hub must be online when homebridge is booting, otherwise it won't be able to discover activities and configure accessories. Timeout are handled only during refresh process (after homebridge boot and plugin init)

brummbaer commented 2 years ago

Hi, I can do that gladly. Unfortunately, I can't say exactly when it will start sending these messages after the hub is turned off. They are also repeated every 10 seconds.

I now understood that the hub must be on when homebridge starts. Sorry for that.

[11/24/2021, 2:47:50 PM] [Heimkino] (Heimkino)ERROR (5)- refreshCurrentActivity Error: WebSocket closed with reason: undefined (undefined). - Stack : Error: WebSocket closed with reason: undefined (undefined).
    at WebSocketAsPromised._handleClose (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:353:19)
    at WebSocket.listener (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:311:64)
    at WebSocket.emit (node:events:390:28)
    at WebSocket.emitClose (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:188:12)
    at ClientRequest.<anonymous> (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:580:15)
    at ClientRequest.emit (node:events:390:28)
    at Socket.socketErrorListener (node:_http_client:447:9)
    at Socket.emit (node:events:390:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
[11/24/2021, 2:47:50 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 2:47:50 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 2:47:50 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 2:47:50 PM] [Heimkino] (Heimkino)WARNING - socket closed

and with resetting counter refresh?:

[11/24/2021, 3:16:27 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 3:16:27 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 3:16:27 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 3:16:27 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 3:16:27 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : NO refresh done since too much socket errors - will retry later
[11/24/2021, 3:18:07 PM] [Heimkino] (Heimkino)WARNING - refreshCurrentActivity : Resetting counter after network loss, trying to refresh
[11/24/2021, 3:18:10 PM] [Heimkino] (Heimkino)ERROR (1)- refreshCurrentActivity Error: WebSocket closed with reason: undefined (undefined). - Stack : Error: WebSocket closed with reason: undefined (undefined).
    at WebSocketAsPromised._handleClose (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:353:19)
    at WebSocket.listener (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:311:64)
    at WebSocket.emit (node:events:390:28)
    at WebSocket.emitClose (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:188:12)
    at ClientRequest.<anonymous> (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:580:15)
    at ClientRequest.emit (node:events:390:28)
    at Socket.socketErrorListener (node:_http_client:447:9)
    at Socket.emit (node:events:390:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
[11/24/2021, 3:18:10 PM] [Heimkino] (Heimkino)WARNING - socket closed
Gullwingdmc commented 2 years ago

I tried running the plugin as a Child Bridge and re-adding the other 2 hubs. I have the same problem. The problem rotates between the 3 hubs. Sometimes all 3 work, other times 2 will start throwing this error and the third will still work. In my case the Living Room hub is the primary and the Kitchen and Bedroom are secondary hubs.

[24/11/2021, 10:44:19] [Living Room] (Kitchen)INFO - Loading activities... [24/11/2021, 10:44:19] [Living Room] (Bedroom)INFO - Loading activities... [24/11/2021, 10:44:29] [Living Room] (Kitchen)Error - Error retrieving info from hub : network timeout at: http://192.168.1.190:8088/-(4859) [24/11/2021, 10:44:29] [Living Room] (Bedroom)Error - Error retrieving info from hub : network timeout at: http://192.168.1.183:8088/-(4859)

brummbaer commented 2 years ago

and this is the first message after i switch the hub "hard" off. 

[11/24/2021, 5:18:52 PM] [FritzPlatform] Fernseher (smarthome-switch): OFF
[11/24/2021, 5:25:33 PM] [homebridge-harmony] This plugin slows down Homebridge. The read handler for the characteristic 'Active' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.
....
[11/24/2021, 5:35:05 PM] [Heimkino] (Heimkino)ERROR (1)- refreshCurrentActivity Error: WebSocket closed with reason: undefined (undefined). - Stack : Error: WebSocket closed with reason: undefined (undefined).
    at WebSocketAsPromised._handleClose (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:353:19)
    at WebSocket.listener (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:311:64)
    at WebSocket.emit (node:events:390:28)
    at WebSocket.emitClose (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:198:10)
    at Receiver.receiverOnFinish (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:825:20)
    at Receiver.emit (node:events:390:28)
    at finish (node:internal/streams/writable:750:10)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
[11/24/2021, 5:35:05 PM] [Heimkino] (Heimkino)WARNING - socket closed
brummbaer commented 2 years ago

@Gullwingdmc are the hubs running continuously or do you also switch off the hubs or deactivate the WLAN? #

Gullwingdmc commented 2 years ago

@brummbaer Continuous. They are always powered and available through the app or Alexa. So I don’t believe it’s a problem with the harmony hubs. However, if I power cycle the harmony hubs that are throwing errors, everything starts working.

nicoduj commented 2 years ago

What homebridge stack are you using (hoobs or something else ?)

Gullwingdmc commented 2 years ago

@nicoduj We’re running the Homebridge Raspberry Pi image, on a Pi Zero W.

nicoduj commented 2 years ago

Hum, ok . In your homebridge conf did you set a range of port of external accessories ? When the problem happens, if you go insiste the container , can you ping / reach the hub ?

brummbaer commented 2 years ago

I think I have solved the initial "harmony hub must be turned on when HomeKit is restarted"-Problem then. But I have updated my hombridge in docker to Version v1.3.8. and this refreshCurrentActivity Error still comes every 10 seconds when the harmony hub is off again after about 10 minutes.

[11/25/2021, 11:41:53 AM] [FritzPlatform] Fernseher (smarthome-switch): OFF
[11/25/2021, 11:45:36 AM] [homebridge-harmony] This plugin slows down Homebridge. The read handler for the characteristic 'Active' didn't respond at all!. Please check that you properly call the callback! See https://git.io/JtMGR for more info.
[11/25/2021, 11:57:51 AM] [Heimkino] (Heimkino)ERROR (1)- refreshCurrentActivity Error: WebSocket closed with reason: undefined (undefined). - Stack : Error: WebSocket closed with reason: undefined (undefined).
    at WebSocketAsPromised._handleClose (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:353:19)
    at WebSocket.listener (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:311:64)
    at WebSocket.emit (node:events:390:28)
    at WebSocket.emitClose (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:198:10)
    at Receiver.receiverOnFinish (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:825:20)
    at Receiver.emit (node:events:390:28)
    at finish (node:internal/streams/writable:750:10)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
[11/25/2021, 11:57:51 AM] [Heimkino] (Heimkino)WARNING - socket closed
[11/25/2021, 11:58:04 AM] [Heimkino] (Heimkino)ERROR (2)- refreshCurrentActivity Error: WebSocket closed with reason: undefined (undefined). - Stack : Error: WebSocket closed with reason: undefined (undefined).
    at WebSocketAsPromised._handleClose (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:353:19)
    at WebSocket.listener (/homebridge/node_modules/homebridge-harmony/node_modules/websocket-as-promised/src/index.js:311:64)
    at WebSocket.emit (node:events:390:28)
    at WebSocket.emitClose (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:188:12)
    at ClientRequest.<anonymous> (/homebridge/node_modules/homebridge-harmony/node_modules/ws/lib/websocket.js:580:15)
    at ClientRequest.emit (node:events:390:28)
    at Socket.socketErrorListener (node:_http_client:447:9)
    at Socket.emit (node:events:390:28)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
[11/25/2021, 11:58:04 AM] [Heimkino] (Heimkino)WARNING - socket closed
nicoduj commented 2 years ago

Just to clarify hubName property is used for autodiscovery (without fixed ip), so trying without it could help (a dedicated lib is used for that and should not be activated if option is not set, and you have a fixed ip set which is more reliable in my opinion). will try to check this issue, but As I allready mention don't have time to code currently, sorry guys.

brummbaer commented 2 years ago

Ok, absolutely no problem and thank you very much. My workaround for this little problem is to set DELAY_BEFORE_RETRY_AFTER_NETWORK_LOSS to a very high value. Then the log is not flooded with the messages. This also has no effect when controlling the restarted HarmonyHub later.

{
            "name": "Heimkino",
            "hubIP": "192.168.3.87",
            "DELAY_BEFORE_RETRY_AFTER_NETWORK_LOSS": 36000000,
            "HUB_CONNECT_TIMEOUT": 120000,
            "HUB_SEND_TIMEOUT": 30000,
            "TVAccessory": true,
            "configureAccesscontrol": false,
            "mainActivity": "Heimkino Apple TV",
            "playPauseBehavior": true,
            "numberOfCommandsSentForVolumeControl": 4,
            "switchAccessories": true,
            "publishGeneralVolumeSlider": false,
            "publishGeneralVolumeSwitches": false,
            "linkVolumeControlToTV": false,
            "publishSwitchActivitiesAsIndividualAccessories": false,
            "platform": "HarmonyHubWebSocket"
        },
Gullwingdmc commented 2 years ago

@nicoduj Should we remove the value next to hubName, or remove the line all together? All hubs are fixed IP for me.

nicoduj commented 2 years ago

@Gullwingdmc removing the line is better.

Gullwingdmc commented 2 years ago

@nicoduj Sounds good. Just did a ping from the HomeBridge terminal and it can’t reach my harmony hubs right now. Which I’m guessing is the reason for this problem. This makes no sense though, because I can reach the hubs from the app on my phone, Alexa, IFTTT. Unless those are all reaching it via the web and the hub is just not responding to local commands. I can’t ping it from my iMac either

nicoduj commented 2 years ago

@Gullwingdmc ok, so maybe a local network issue : do you have a mesh network ? could be interesting to see if it happens on a renewal of IP ? just a guess. What kind of wifi / router are you using ?

Gullwingdmc commented 2 years ago

Yeah we do have a mesh. ASUS ZenWIFI AX. That’s not new though. You think changing the fixed IPs could help? Coild explain why restarting the harmony hubs gets them back online briefly.

inspectorgadjet7 commented 2 years ago

I was just coming here to see if anyone else had this same issue. I do have a mesh network as well using ASUS routers. I’m going to try binding the Logitech hubs to the main router to see if it helps.

Gullwingdmc commented 2 years ago

I was just coming here to see if anyone else had this same issue. I do have a mesh network as well using ASUS routers. I’m going to try binding the Logitech hubs to the main router to see if it helps.

That’s interesting. I wonder if it’s an ASUS issue. How do you bind a device to a specific node? I’ve been trying to figure that out, but it seems like they don’t make it easy.

inspectorgadjet7 commented 2 years ago

I was just coming here to see if anyone else had this same issue. I do have a mesh network as well using ASUS routers. I’m going to try binding the Logitech hubs to the main router to see if it helps.

That’s interesting. I wonder if it’s an ASUS issue. How do you bind a device to a specific node? I’ve been trying to figure that out, but it seems like they don’t make it easy.

In the router web interface there is a little link icon next to devices in the AI Mesh section, or in the router app, the link icon is in the devices section.

Gullwingdmc commented 2 years ago

Thanks @inspectorgadjet7 ! I’ll give that a try.

inspectorgadjet7 commented 2 years ago

In addition to the symptoms already mentioned in this thread, I have a new one that I’ve only noticed in the logs since yesterday: [12/9/2021, 8:26:59 AM] [homebridge-harmony] This plugin slows down Homebridge. The read handler for the characteristic 'Active' didn't respond at all!. Please check that you properly call the callback! See https://git.io

nicoduj commented 2 years ago

@inspectorgadjet7 This warning is mainly due to slow response from the bridge, and if you have a lot of activities/ device, can be worst. =i have seen very often that it can be related to mesh wifi configuration.

Gullwingdmc commented 2 years ago

@nicoduj This issue seems to have been solved by the latest version of the harmony hub firmware. Version 4.15.307. Released March 2022 https://support.myharmony.com/en-us/release-notes