node-red-contrib-home-assistant-websocket icon indicating copy to clipboard operation
node-red-contrib-home-assistant-websocket copied to clipboard
verified publisher icon zachowj

After upgrade to HA 2022.7.0 or later, Node-Red disconnects

Open ThomasPrior opened this issue 3 years ago • 14 comments

Describe the bug

Behavior with HomeAssistant 2022.7.0 or later:

HomeAssistant starts NodeRed connects After a short period of time, the following lines are displayed in the log:

11 Jul 14:04:39 - [debug] [api-call-service:Turn On Working Lights Seg0] Calling Service: light:turn_on -- {"entity_id":"light.hannah_meeting_lights","effect":"Solid","brightness":"100","color_name":"green"}
11 Jul 14:04:52 - [debug] [api-call-service:Turn On Meeting Lights Seg1] Calling Service: light:turn_on -- {"entity_id":"light.tom_meeting_lights","effect":"Solid","brightness":"25","color_name":"blue"}
11 Jul 14:04:54 - [debug] [api-call-service:Turn Off Light Seg1] Calling Service: light:turn_off -- {"entity_id":"light.tom_meeting_lights"}
11 Jul 14:05:08 - [debug] [inject:4AM] repeat = 3600000
11 Jul 14:05:08 - [debug] [api-call-service:ecce1285.45fd9] Calling Service: shell_command:google_token -- {}
Received event for unknown subscription 18. Unsubscribing.
Received event for unknown subscription 9. Unsubscribing.

No further state changes are passed from HomeAssistant to Node-Red

Issue is not present before HomeAssistant 2022.7 and I'm aware that this is likely an issue I need to raise on that project, however I can't work out what flows or subscriptions are causing the issue. Any pointers in the right direction would be appreciated.

To Reproduce

No response

Expected behavior

HA starts NodeRed connects State changes are passed from HomeAssistant to Node-Red

Screenshots

image

Example Flow

No response

This package's version (not the Home Assistant add-on version)

0.43.1

Is Node-RED running in Docker?

Yes

Node-RED version

2.2.2

Node.js version

14.18.2

Additional context

No response

ThomasPrior avatar Jul 11 '22 13:07 ThomasPrior

Is this something that happens on every boot? or randomly?

This will be hard to track unless you can find what HA is sending NR at the time of the error. Turn on debug for the websocket_api in HA and it will print out all the messages received and sent.

logger:
  default: error
  logs:
    homeassistant.components.websocket_api: debug

zachowj avatar Jul 11 '22 21:07 zachowj

Thanks, I'll collect some extra logs tonight.

This happens within a few seconds of HA 2022.7+ starting up. If all flows are restarted or node red container is restarted, state changes come back again for another 30 seconds or so before the same unsubscribe messages are posted to the NR log.

ThomasPrior avatar Jul 11 '22 21:07 ThomasPrior

HA:


2022-07-11T23:10:08.707061245Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777827339520] Received {'type': 'unsubscribe_events', 'subscription': 7, 'id': 40}
2022-07-11T23:10:08.708195046Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777827339520] Sending {"id":40,"type":"result","success":true,"result":null}
2022-07-11T23:10:08.708506970Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777827339520] Received {'type': 'unsubscribe_events', 'subscription': 14, 'id': 41}
2022-07-11T23:10:08.709489667Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777827339520] Sending {"id":41,"type":"result","success":true,"result":null}
2022-07-11T23:10:08.709891087Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777803450160] Received {'type': 'unsubscribe_events', 'subscription': 2, 'id': 70}
2022-07-11T23:10:08.710047238Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777803450160] Sending {"id":70,"type":"result","success":true,"result":null}

NR:

2022-07-11T23:10:08.703907195Z Received event for unknown subscription 7. Unsubscribing.
2022-07-11T23:10:08.705011825Z Received event for unknown subscription 14. Unsubscribing.
2022-07-11T23:09:51.483286583Z 12 Jul 00:09:51 - [debug] [api-call-service:Turn Off Light Seg1] Calling Service: {"domain":"light","service":"turn_off","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights"}}
2022-07-11T23:09:51.454062127Z 12 Jul 00:09:51 - [debug] [api-call-service:Turn Off Light Seg1] Calling Service: {"domain":"light","service":"turn_off","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights"}}
2022-07-11T23:09:49.128803133Z 12 Jul 00:09:49 - [debug] [api-call-service:Turn On Meeting Lights Seg1] Calling Service: {"domain":"light","service":"turn_on","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights","effect":"Solid","brightness":"25","color_name":"blue"}}
2022-07-11T23:09:41.651674746Z 12 Jul 00:09:41 - [debug] [server:Home Assistant] HA State: running

ThomasPrior avatar Jul 11 '22 23:07 ThomasPrior

Looking for what happened before the first line in HA log

2022-07-11T23:10:08.707061245Z 2022-07-12 00:10:08 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139777827339520] Received {'type': 'unsubscribe_events', 'subscription': 7, 'id': 40}

zachowj avatar Jul 11 '22 23:07 zachowj

Yep, it's unfortunately something I can't share for privacy reasons, however the log configuration you sent earlier was the thing that has helped me identify what may be causing the issue in that instance.

I've removed the offending sensor mentioned in the unsubscribe message and restarted, but the issue persists - this time with a different entity mentioned:

2022-07-11T23:21:18.352583181Z 12 Jul 00:21:18 - [info] [hue-bridge:Philips hue] Processing bridge resources…
2022-07-11T23:22:32.256211840Z (node:17) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
2022-07-11T23:21:18.357636342Z 12 Jul 00:21:18 - [info] [hue-bridge:Philips hue] Initial emit of resource states…
2022-07-11T23:21:18.861053767Z 12 Jul 00:21:18 - [info] [hue-bridge:Philips hue] Keeping nodes up-to-date…
2022-07-11T23:21:18.861260855Z 12 Jul 00:21:18 - [info] [hue-bridge:Philips hue] Subscribing to bridge events…
2022-07-11T23:21:43.809953370Z 12 Jul 00:21:43 - [debug] [api-call-service:Turn On Video Meeting Light Seg1] Calling Service: {"domain":"light","service":"turn_on","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights","effect":"Solid","brightness":"25","color_name":"red"}}
2022-07-11T23:22:30.229981612Z 12 Jul 00:22:30 - [debug] [api-call-service:Turn On Meeting Lights Seg1] Calling Service: {"domain":"light","service":"turn_on","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights","effect":"Solid","brightness":"25","color_name":"blue"}}
2022-07-11T23:22:32.232034873Z Received event for unknown subscription 9. Unsubscribing.
2022-07-11T23:22:32.248025583Z Received event for unknown subscription 22. Unsubscribing.
2022-07-11T23:22:32.239339552Z Received event for unknown subscription 22. Unsubscribing.
2022-07-11T23:22:32.255970024Z (Use `node --trace-warnings ...` to show where the warning was created)
2022-07-11T23:22:32.255797848Z (node:17) UnhandledPromiseRejectionWarning: #<Object>
2022-07-11T23:22:32.256067083Z (node:17) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)

2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_www","old_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":4369,"rx_bytes-r":18375,"latency":14,"uptime":580471,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted,"icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:21:32.224003+00:00","context":{"id":"01G7QS2SA09A4K1TJM455EA52N","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1567,"rx_bytes-r":4689,"latency":12,"uptime":580533,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:22:32.225828+00:00","context":{"id":"01G7QS4KX16HZY0Y9VYR5AJ72K","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:22:32.225828+00:00","context":{"id":"01G7QS4KX16HZY0Y9VYR5AJ72K","parent_id":null,"user_id":null}}}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":9,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_www","old_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":4369,"rx_bytes-r":18375,"latency":14,"uptime":580471,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:21:32.224003+00:00","context":{"id":"01G7QS2SA09A4K1TJM455EA52N","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1567,"rx_bytes-r":4689,"latency":12,"uptime":580533,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:22:32.225828+00:00","context":{"id":"01G7QS4KX16HZY0Y9VYR5AJ72K","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:22:32.225828+00:00","context":{"id":"01G7QS4KX16HZY0Y9VYR5AJ72K","parent_id":null,"user_id":null}}}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":33,"type":"result","success":true,"result":null}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Received {'type': 'unsubscribe_events', 'subscription': 9, 'id': 33}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_wlan","old_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":883765,"rx_bytes-r":9778,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:21:32.231794+00:00","context":{"id":"01G7QS2SA7ZZX208TSFN97EAPC","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":747734,"rx_bytes-r":11484,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:22:32.244310+00:00","context":{"id":"01G7QS4KXMX7WQVXDE4SMHQA9R","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:22:32.244310+00:00","context":{"id":"01G7QS4KXMX7WQVXDE4SMHQA9R","parent_id":null,"user_id":null}}}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 34}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":34,"type":"result","success":true,"result":null}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 35}
2022-07-12 00:22:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698461237696] Sending {"id":35,"type":"result","success":false,"error":{"code":"not_found","message":"Subscription not found."}}

ThomasPrior avatar Jul 11 '22 23:07 ThomasPrior

Another example:

2022-07-11T23:55:32.284592211Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":31,"type":"result","success":true,"result":null}
2022-07-11T23:55:32.276463995Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 9, 'id': 31}

2022-07-11T23:55:32.270351720Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_www","old_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1553,"rx_bytes-r":6562,"latency":14,"uptime":582457,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:54:32.264463+00:00","context":{"id":"01G7QTZ6Y8WESH3TGBWKH1QE8J","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1372,"rx_bytes-r":4380,"latency":13,"uptime":582520,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:55:32.264814+00:00","context":{"id":"01G7QV11H8YGR1YMBGWZBN1JYA","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:55:32.264814+00:00","context":{"id":"01G7QV11H8YGR1YMBGWZBN1JYA","parent_id":null,"user_id":null}}}
2022-07-11T23:55:32.291526731Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_wlan","old_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":1595475,"rx_bytes-r":8519,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:54:32.270525+00:00","context":{"id":"01G7QTZ6YE8JFFM3D3DDZV9GF6","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":181384,"rx_bytes-r":7007,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:55:32.274729+00:00","context":{"id":"01G7QV11HJ093XRYJ83KE0GT4M","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:55:32.274729+00:00","context":{"id":"01G7QV11HJ093XRYJ83KE0GT4M","parent_id":null,"user_id":null}}}
2022-07-11T23:55:32.295241910Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 32}
2022-07-11T23:55:32.295407736Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":32,"type":"result","success":true,"result":null}
2022-07-11T23:55:32.295599647Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 33}

2022-07-11T23:55:32.295791940Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":33,"type":"result","success":false,"error":{"code":"not_found","message":"Subscription not found."}}

2022-07-11T23:55:32.272099741Z Received event for unknown subscription 22. Unsubscribing.
2022-07-11T23:55:32.271111448Z Received event for unknown subscription 9. Unsubscribing.
2022-07-11T23:55:32.294844485Z (node:17) UnhandledPromiseRejectionWarning: #<Object>
2022-07-11T23:55:32.280989418Z Received event for unknown subscription 22. Unsubscribing.
2022-07-11T23:55:32.295053632Z (node:17) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)
2022-07-11T23:55:05.947233386Z 12 Jul 00:55:05 - [info] [hue-bridge:Philips hue] Processing bridge resources…
2022-07-11T23:55:05.952154165Z 12 Jul 00:55:05 - [info] [hue-bridge:Philips hue] Initial emit of resource states…
2022-07-11T23:55:06.455419413Z 12 Jul 00:55:06 - [info] [hue-bridge:Philips hue] Keeping nodes up-to-date…
2022-07-11T23:55:06.455607464Z 12 Jul 00:55:06 - [info] [hue-bridge:Philips hue] Subscribing to bridge events…

ThomasPrior avatar Jul 11 '22 23:07 ThomasPrior

You could try placing this at the top of the settings.js in your NR config directory.

process.on('unhandledRejection', (reason, p) => {
  console.log('Unhandled Rejection: ', p, 'reason:', reason);
});

zachowj avatar Jul 12 '22 00:07 zachowj

Thank you, trying that now.

ThomasPrior avatar Jul 12 '22 00:07 ThomasPrior

No luck I'm afraid. I'm wondering if this is somehow related to https://github.com/home-assistant/core/pull/74971?

12 Jul 01:11:41 - [debug] [api-call-service:Turn Off Light Seg1] Calling Service: {"domain":"light","service":"turn_off","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights"}}
12 Jul 01:11:41 - [debug] [api-call-service:Set Nighttime Theme] Calling Service: {"domain":"frontend","service":"set_theme","target":{},"data":{"name":"midnight"}}
12 Jul 01:11:41 - [debug] [api-call-service:Turn Off Candles] Calling Service: {"domain":"switch","service":"turn_off","target":{"entity_id":"switch.candles"},"data":{"entity_id":"switch.candles"}}
12 Jul 01:11:41 - [debug] [within-time-switch:a1133671.5aeb88] --------- within-time-switch - input
12 Jul 01:11:41 - [debug] [within-time-switch:a1133671.5aeb88] out of time - send msg to second output 7/12/2022 1:11:41 AM
12 Jul 01:11:53 - [debug] [api-call-service:Turn Off Light Seg1] Calling Service: {"domain":"light","service":"turn_off","target":{"entity_id":"light.tom_meeting_lights"},"data":{"entity_id":"light.tom_meeting_lights"}}
Received event for unknown subscription 9. Unsubscribing.
Received event for unknown subscription 23. Unsubscribing.


2022-07-11T23:55:32.270351720Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_www","old_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1553,"rx_bytes-r":6562,"latency":14,"uptime":582457,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:54:32.264463+00:00","context":{"id":"01G7QTZ6Y8WESH3TGBWKH1QE8J","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_www","state":"OK","attributes":{"subsystem":"www","status":"ok","tx_bytes-r":1372,"rx_bytes-r":4380,"latency":13,"uptime":582520,"drops":104,"xput_up":37.042,"xput_down":235.34,"speedtest_status":"Success","speedtest_lastrun":1657573496,"speedtest_ping":18,"gw_mac":"redacted","icon":"mdi:web","friendly_name":"UniFi Gateway WWW"},"last_changed":"2022-07-11T23:20:32.101492+00:00","last_updated":"2022-07-11T23:55:32.264814+00:00","context":{"id":"01G7QV11H8YGR1YMBGWZBN1JYA","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:55:32.264814+00:00","context":{"id":"01G7QV11H8YGR1YMBGWZBN1JYA","parent_id":null,"user_id":null}}}
2022-07-11T23:55:32.276463995Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 9, 'id': 31}
2022-07-11T23:55:32.284592211Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":31,"type":"result","success":true,"result":null}
2022-07-11T23:55:32.291526731Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":22,"type":"event","event":{"event_type":"state_changed","data":{"entity_id":"sensor.unifi_gateway_wlan","old_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":1595475,"rx_bytes-r":8519,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:54:32.270525+00:00","context":{"id":"01G7QTZ6YE8JFFM3D3DDZV9GF6","parent_id":null,"user_id":null}},"new_state":{"entity_id":"sensor.unifi_gateway_wlan","state":"OK","attributes":{"subsystem":"wlan","num_user":38,"num_guest":0,"num_iot":0,"tx_bytes-r":181384,"rx_bytes-r":7007,"status":"ok","num_ap":1,"num_adopted":1,"num_disabled":0,"num_disconnected":0,"num_pending":0,"icon":"mdi:wifi","friendly_name":"UniFi Gateway WLAN"},"last_changed":"2022-07-11T23:20:32.266305+00:00","last_updated":"2022-07-11T23:55:32.274729+00:00","context":{"id":"01G7QV11HJ093XRYJ83KE0GT4M","parent_id":null,"user_id":null}}},"origin":"LOCAL","time_fired":"2022-07-11T23:55:32.274729+00:00","context":{"id":"01G7QV11HJ093XRYJ83KE0GT4M","parent_id":null,"user_id":null}}}
2022-07-11T23:55:32.295241910Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 32}
2022-07-11T23:55:32.295407736Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":32,"type":"result","success":true,"result":null}
2022-07-11T23:55:32.295599647Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Received {'type': 'unsubscribe_events', 'subscription': 22, 'id': 33}

2022-07-11T23:55:32.295791940Z 2022-07-12 00:55:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140698447874368] Sending {"id":33,"type":"result","success":false,"error":{"code":"not_found","message":"Subscription not found."}}

ThomasPrior avatar Jul 12 '22 00:07 ThomasPrior

I too am experiencing the same issue, I was discussing on discord yesterday with kermit and he asked to post logs here, however I had to turn off debug on HA as the log got upto 100's of megs within a couple hours.. I noticed this morning that there was a node-red update so thought Great maybe there has been a fix so I have upgraded and unfortunately it's still breaking. The difference now is that I see an error and NR actually says crashed and it's trying to restart.

I did try rolling back HA to .6 version but it made no difference.

I did notice the older version of NR would recover if I deployed a flow- so a restart wasn't necessary.

18 Jul 11:55:12 - [debug] [api-call-service:Kitchen Island] Calling Service: {"domain":"light","service":"turn_off","target":{"entity_id":"light.kitchen_counter"},"data":{"entity_id":"light.kitchen_counter"}}
Received event for unknown subscription 3. Unsubscribing.
Received event for unknown subscription 9. Unsubscribing.
Received event for unknown subscription 3. Unsubscribing.
Received event for unknown subscription 9. Unsubscribing.
18 Jul 12:00:00 - [red] Uncaught Exception:
18 Jul 12:00:00 - [error] UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "#<Object>".
[12:00:00] WARNING: Node-RED crashed, halting add-on
[12:00:00] INFO: Node-RED stoped, restarting...
s6-rc: info: service legacy-services: stopping
[12:00:00] INFO: Node-RED stoped, restarting...

aussybob avatar Jul 18 '22 02:07 aussybob

I'm also having a similar issue, but with slightly different symptoms. After a few hours node red seems to stop receiving (or reacting to) any changes. I can see everything coming into HA just fine.

I see the below in my logs, and it seems to periodically restart. Unsure if it's related. I bumped everything to debug logging and I'll update from there.

22 Jul 03:16:02 - [info] [server:Home Assistant] Connecting to http://10.0.0.10:8123
22 Jul 03:16:02 - [info] [server:Home Assistant] Connected to http://10.0.0.10:8123
22 Jul 03:16:30 - [info] Stopping flows
22 Jul 03:16:30 - [info] [server:Home Assistant] Closing connection to http://10.0.0.10:8123
22 Jul 03:16:30 - [info] Stopped flows
22 Jul 03:16:30 - [info] Updated flows
22 Jul 03:16:30 - [info] Starting flows
22 Jul 03:16:30 - [info] Started flows
22 Jul 03:16:30 - [info] [server:Home Assistant] Connecting to http://10.0.0.10:8123
22 Jul 03:16:30 - [info] [server:Home Assistant] Connected to http://10.0.0.10:8123
22 Jul 13:20:42 - [info] Stopping flows
22 Jul 13:20:42 - [info] [server:Home Assistant] Closing connection to http://10.0.0.10:8123
22 Jul 13:20:42 - [info] Stopped flows
22 Jul 13:20:42 - [info] Updated flows
22 Jul 13:20:42 - [info] Starting flo
22 Jul 13:20:42 - [info] Started flows

coltoneshaw avatar Jul 22 '22 13:07 coltoneshaw

Does anyone know whether there has been any update on this issue? I had to downgrade to 2022.5.5 to make NR stable. Seems like it's been abandoned?

aussybob avatar Aug 01 '22 00:08 aussybob

Does anyone know whether there has been any update on this issue? I had to downgrade to 2022.5.5 to make NR stable. Seems like it's been abandoned?

I'm afraid I haven't gotten any further with this

ThomasPrior avatar Aug 01 '22 13:08 ThomasPrior

Not sure if anyone is tracking this issue but I can verify it is still happening with the latest version 2022.8.2. Should this be raised elsewhere? Not sure what others are doing to get around this, I had to downgrade to 2022.5.5.

aussybob avatar Aug 08 '22 23:08 aussybob

I've had to recreate my automations as best I could in HomeAssistant natively.

ThomasPrior avatar Aug 17 '22 15:08 ThomasPrior

I've had to recreate my automations as best I could in HomeAssistant natively.

Oh dear.. That makes me very sad! I have a tonne of automations to convert. Why is this happening to a small portion of users? When I was on discord someone mentioned this issue is connected to unifi equipment, is this a fact? Has the issue been raised with the home assistant devs?

aussybob avatar Aug 17 '22 23:08 aussybob

I haven't heard of it being related to Unifi but I do have Unifi hardware.

I haven't reported it on the homeassistant repository as homeassistant itself seems to be working fine and I can't find any further information that would indicate it's a HA problem, at least until now.

ThomasPrior avatar Aug 17 '22 23:08 ThomasPrior

Does anyone know whether there has been any update on this issue? I had to downgrade to 2022.5.5 to make NR stable. Seems like it's been abandoned?

Short answer: I haven't found the time to look any further into it.

From what I can see NR is receiving an event from HA that it is not expecting. Why this is happening I have no idea.

The logs provided don't have any useful information. I'm looking for the message that HA sends right before NR logs Received event for unknown subscription 3. Unsubscribing.

Why is this happening to a small portion of users?

My guess is it's caused by a custom integration and a unique circumstance.

zachowj avatar Aug 18 '22 00:08 zachowj

I haven't heard of it being related to Unifi but I do have Unifi hardware.

I haven't reported it on the homeassistant repository as homeassistant itself seems to be working fine and I can't find any further information that would indicate it's a HA problem, at least until now.

image

aussybob avatar Aug 18 '22 01:08 aussybob

That was me making a random guess.

zachowj avatar Aug 18 '22 01:08 zachowj

@ThomasPrior are you running the Node Red Companion HACS integration? Could this be the problem? Or maybe the webhook node?

aussybob avatar Aug 18 '22 01:08 aussybob

@ThomasPrior are you running the Node Red Companion HACS integration? Could this be the problem? Or maybe the webhook node?

I'm not using either of those items

ThomasPrior avatar Aug 18 '22 04:08 ThomasPrior

You can edit HA websocket lib to output the message that causes this error.

Inside the NR config directory there should be a node_modules/home-assistant-js-websocket/dist directory. If you edit the haws.cjs file and insert the below on line 177. Next time the error is throw in the NR logs it will show the exact message that caused the error.

  console.warn(`Message: ${message}`);
  console.warn(`Received event for unknown subscription ${message.id}. Unsubscribing.`);

zachowj avatar Aug 18 '22 14:08 zachowj

Interesting. Let me play with this. What I'm seeing is it might be related to people running HA in Docker. Mine will completely stop sending any requests over after a few hours of inactivity.

coltoneshaw avatar Aug 18 '22 14:08 coltoneshaw

@coltoneshaw if you do not see Received event for unknown subscription 3. Unsubscribing. in your logs. Your issue is not related to this one.

Try turning on the heartbeat option in the server config node options.

zachowj avatar Aug 18 '22 14:08 zachowj

Just did that. I'll update in a few hours if i see it. I swear I replied to another issue related to mine on this repo, but I'm not finding it, so I was confused.

My behavior is that I can deploy a new flow, then usually, after some time, nothing works. If I redeploy it again, it works again. I don't yet see that specific error in my logs. I see the below where it seems to reconnect randomly.

2022-07-31T20:52:07.154406045Z 31 Jul 20:52:07 - [debug] [api-current-state:State ON - Office Lamp 1] instantiated node, name: State ON - Office Lamp 1
2022-07-31T20:52:07.154706670Z 31 Jul 20:52:07 - [debug] [api-call-service:OFF - Office Lamp 2] instantiated node, name: OFF - Office Lamp 2
2022-07-31T20:52:07.154919962Z 31 Jul 20:52:07 - [debug] [api-current-state:State ON - Office Lamp 2] instantiated node, name: State ON - Office Lamp 2
2022-07-31T20:52:07.155692629Z 31 Jul 20:52:07 - [debug] [api-current-state:State On - Office Fan] instantiated node, name: State On - Office Fan
2022-07-31T20:52:07.155957129Z 31 Jul 20:52:07 - [debug] [api-call-service:Fan Speed Med] instantiated node, name: Fan Speed Med
2022-07-31T20:52:07.156477337Z 31 Jul 20:52:07 - [debug] [api-call-service:Fan Speed Hi] instantiated node, name: Fan Speed Hi
2022-07-31T20:52:07.156904462Z 31 Jul 20:52:07 - [debug] [api-call-service:Fan Speed Low] instantiated node, name: Fan Speed Low
2022-07-31T20:52:07.157774920Z 31 Jul 20:52:07 - [debug] [server-events:46c1d9e172f61b9c] instantiated node, name: undefined
2022-07-31T20:52:07.161014920Z 31 Jul 20:52:07 - [debug] [ha-device:0d17348a6c516000] instantiated node, name: undefined
2022-07-31T20:52:07.163245087Z 31 Jul 20:52:07 - [info] Started flows
2022-07-31T20:52:07.166907754Z 31 Jul 20:52:07 - [info] [server:Home Assistant] Connecting to http://10.0.0.10:8123
2022-07-31T20:53:14.207446674Z 31 Jul 20:53:14 - [info] [server:Home Assistant] Connected to http://10.0.0.10:8123
2022-07-31T20:53:14.234225174Z 31 Jul 20:53:14 - [debug] [server:Home Assistant] States Loaded
2022-07-31T20:53:14.239934882Z 31 Jul 20:53:14 - [debug] [server:Home Assistant] Integration: loaded
2022-07-31T20:53:14.240702965Z 31 Jul 20:53:14 - [debug] [ha-device:0d17348a6c516000] Registering with Home Assistant
2022-07-31T20:53:14.265675882Z 31 Jul 20:53:14 - [debug] [server:Home Assistant] HA State: running
2022-07-31T20:53:14.291736257Z 31 Jul 20:53:14 - [debug] [server:Home Assistant] Services Loaded
2022-07-31T20:59:02.458846793Z 31 Jul 20:59:02 - [info] [server:Home Assistant] Connection closed to http://10.0.0.10:8123
2022-07-31T20:59:02.461819335Z 31 Jul 20:59:02 - [info] [server:Home Assistant] Connecting to http://10.0.0.10:8123
2022-07-31T20:59:02.468799001Z 31 Jul 20:59:02 - [info] [server:Home Assistant] Connected to http://10.0.0.10:8123
2022-07-31T20:59:02.477913168Z 31 Jul 20:59:02 - [debug] [server:Home Assistant] States Loaded
2022-07-31T20:59:02.485311501Z 31 Jul 20:59:02 - [debug] [server:Home Assistant] Services Loaded
2022-07-31T20:59:02.487985751Z 31 Jul 20:59:02 - [debug] [server:Home Assistant] Integration: loaded
2022-07-31T20:59:02.488214668Z 31 Jul 20:59:02 - [debug] [ha-device:0d17348a6c516000] Registering with Home Assistant
2022-07-31T20:59:02.488980876Z 31 Jul 20:59:02 - [debug] [server:Home Assistant] HA State: running

coltoneshaw avatar Aug 18 '22 14:08 coltoneshaw

Annoyingly enough, I can't replicate the behaviour any more.

Things that have changed in my setup since:

  • WLED updated from 13.1 to 13.2
  • No longer having the EthermineInfo custom component installed having moved it to a dedicated development instance.
  • HA updated to 2022.8.6
  • node-red-contrib-home-assistant-websocket updated to 0.44.0
  • Node-Red updated to 3.0.2

I will try to replicate the problematic setup as best I can over the weekend. I used to be able to trigger the disconnect very reliably by toggling a WLED on/off, but again that's not happening now. The previously unshared-for-privacy-reasons was a friend's mining address via added EthermineInfo.

The HA problem I thought may be relevant and linked earlier was merged in 2022.7.4 and specifically caused issues when setting a bulb colour by name and only affected automations.

ThomasPrior avatar Aug 18 '22 15:08 ThomasPrior

This issue has been automatically marked as abandoned because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] avatar Sep 18 '22 06:09 github-actions[bot]