websocket connection being made before component loaded #250

steve28 · 2020-07-02T14:16:32Z

#247 is still happening in HA 0.112.0 and node-red-contrib-home-assistant-websocket 0.22.6

With debug logs turned on in the custom_component I still get this at startup:

2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:46 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140084432147024] Received invalid command: nodered/discovery
2020-07-02 07:03:52 INFO (MainThread) [custom_components.nodered] 
-------------------------------------------------------------------
nodered
Version: 0.4.4
This is a custom integration
If you have any issues with this you need to open an issue here:
https://github.com/zachowj/hass-node-red/issues
-------------------------------------------------------------------

Describe the bug

When I restart HA with node-red already running, all entities created by node-red-contrib-home-assistant-websocket are unavailable until I restart node-red.

To Reproduce

Steps to reproduce the behavior:

Restart HA with node-red already running

Environment (please complete the following information):

Node Red Version: 1.0.6
Node.js Version: 10.20.1
NR Home Assistant Plugin Version: 0.4.4
Is Node Red running in Docker: yes

Other (please complete the following information):

Have you searched previous issues for duplicates?: yes (found my old closed one Restarting HomeAssistant loses all sensors until NR restart #247), but still occurring

Additional context

The text was updated successfully, but these errors were encountered:

DirkMu · 2020-07-03T19:28:36Z

I have a similar issue. Once Home Assistant was restarted the function node seems not to be able to get a connection to Home Assistant and as a result the state of an entity cannot be read. An error "TypeError: Cannot read property 'state' of undefined" is thrown. When the connection to HA is updated via Configurations Node, the connection seems to be re-established and the function node works propery. A restart of the node-red container leads to teh same result.
I am using Home Assistant core on Docker, lastest version 0.112.1 and Node-Red on Docker 1.1.0. node-red-contrib-home-assistant-websocket was installed via palette manager. Lastest version 0.22.6.

bonanitech · 2020-07-04T19:24:12Z

I had a similar issue. For some reason, all entities got duplicated in my case.

I removed the old ones and corrected the Entity ID of the newer ones. Everything is working fine now.

EDIT: By all entities, I mean the ones created by the Node-RED integration.

bonanitech · 2020-07-07T01:56:25Z

It just happened to me, after upgrading HA to 0.112.3 the entities became unavailable. I had to restart Node-RED to have them working again.

zachowj · 2020-07-09T06:19:37Z

Currently remodeling my office so it will about another week before I can look into this.

bonanitech · 2020-07-09T11:33:10Z

Just upgraded HA to 0.112.4 and found this in Node-RED logs.

8 Jul 13:18:15 - [info] [server:Home Assistant] WebSocket Connected to http://10.10.0.6:8123
ERROR: undefined
9 Jul 07:22:32 - [info] [server:Home Assistant] WebSocket Closed http://10.10.0.6:8123
9 Jul 07:22:32 - [info] [server:Home Assistant] WebSocket Connecting http://10.10.0.6:8123
9 Jul 07:22:37 - [info] [server:Home Assistant] WebSocket Connecting http://10.10.0.6:8123
9 Jul 07:22:42 - [info] [server:Home Assistant] WebSocket Connecting http://10.10.0.6:8123
9 Jul 07:22:58 - [info] [server:Home Assistant] WebSocket Connected to http://10.10.0.6:8123
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 1)
(node:16) [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.
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 2)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 3)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 4)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 5)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 6)
9 Jul 07:23:55 - [info] Stopping flows
9 Jul 07:23:55 - [info] [server:Home Assistant] Closing WebSocket http://10.10.0.6:8123
9 Jul 07:23:55 - [info] Stopped flows

Home Assistant logs.

2020-07-09 07:22:53 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for nodered which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:22:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139943654073552] Received invalid command: nodered/discovery
2020-07-09 07:23:48 ERROR (MainThread) [homeassistant.components.script] movie: Error executing script. Service not found for call_service at pos 1: Unable to find service nodered/trigger

I hope this helps in some way.

steve28 · 2020-07-21T20:33:40Z

@zachowj you get a chance to look at this?

zachowj · 2020-07-22T19:35:32Z

I wasn't able to reproduce this 100% of the time so not sure if this will completely fix it but you can try the latest version and test it or wait until I push the next release.

npm install node-red-contrib-home-assistant-websocket@next

You can also change the logging level of NR to debug little more reporting of the client status.

zachowj · 2020-07-23T21:38:08Z

Found another edge case that needs to be fixed.

steve28 · 2020-07-23T21:59:18Z

so... it works sometimes. I did about 6 restarts of HA and 2 of the times it did not work (entities not available in HA).

Here are debug logs from NR when it works:

23 Jul 14:26:07 - [info] [server:Home Assistant] Connection closed to http://192.168.1.8:8123
23 Jul 14:26:07 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:26:12 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:26:17 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:26:17 - [info] [server:Home Assistant] Connected to http://192.168.1.8:8123
23 Jul 14:26:17 - [debug] [server:Home Assistant] States Loaded
23 Jul 14:26:17 - [debug] [server:Home Assistant] Services Loaded
23 Jul 14:26:17 - [debug] [server:Home Assistant] Integration: loaded
23 Jul 14:26:17 - [debug] [ha-entity:Odometer] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:SW Version] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Plugged In] Registering binary_sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:State] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Battery Level] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Range] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Locked] Registering binary_sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Charge State] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:Network Status] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:OpenZWave_Version] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:OZWDaemon_Version] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:QTOpenZWave Version] Registering sensor with HA
23 Jul 14:26:17 - [debug] [ha-entity:OZW Status Timestamp] Registering sensor with HA
23 Jul 14:26:41 - [debug] [server:Home Assistant] HA State: running

and here's what it looks like when it doesn't:

23 Jul 14:27:05 - [info] [server:Home Assistant] Connection closed to http://192.168.1.8:8123
23 Jul 14:27:05 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:27:10 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:27:15 - [info] [server:Home Assistant] Connecting to http://192.168.1.8:8123
23 Jul 14:27:15 - [info] [server:Home Assistant] Connected to http://192.168.1.8:8123
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 1)
(node:16) [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.
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 2)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 3)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 4)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 5)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 6)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 7)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 8)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 9)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 10)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 11)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 12)
(node:16) UnhandledPromiseRejectionWarning: #<Object>
(node:16) 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(). (rejection id: 13)
23 Jul 14:27:15 - [debug] [server:Home Assistant] States Loaded
23 Jul 14:27:16 - [debug] [server:Home Assistant] Services Loaded
23 Jul 14:27:18 - [debug] [alexa-remote-account:e42c377f.df65e8] Alexa-Remote WS-MQTT: Send Ping
23 Jul 14:27:18 - [debug] [alexa-remote-account:e42c377f.df65e8] Alexa-Remote WS-MQTT: Received Pong
23 Jul 14:27:22 - [debug] [server:Home Assistant] Integration: loaded
23 Jul 14:27:22 - [debug] [ha-entity:Odometer] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:SW Version] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Plugged In] Registering binary_sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:State] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Battery Level] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Range] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Locked] Registering binary_sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Charge State] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:Network Status] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:OpenZWave_Version] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:OZWDaemon_Version] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:QTOpenZWave Version] Registering sensor with HA
23 Jul 14:27:22 - [debug] [ha-entity:OZW Status Timestamp] Registering sensor with HA
23 Jul 14:27:40 - [debug] [server:Home Assistant] HA State: running

Here's what happens in HA when the errors pop up in NR:

2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery
2020-07-23 14:27:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140569463666448] Received invalid command: nodered/discovery

This was using version: 0.22.7-dev.8ec47fb2e

zachowj · 2020-07-23T22:36:01Z

Yes, it a race condition between the WebSocket client resubscribing and when the integration is loaded. At the moment I don't have any control over when the WS client sends the resubscribe messages. Still looking into a solution for this.

home-assistant/home-assistant-js-websocket#130

steve28 · 2020-07-27T20:52:54Z

@zachowj could do something as simple as re-connecting when you get HA State: Running event? Even if it thinks it already is... just refresh the connection every time that event is received.

zachowj · 2020-07-29T01:01:15Z

@steve28 Yes, there are probably several different hackish workarounds that could be temporarily implemented. I would rather see some sort of fix implemented upstream.

zachowj · 2020-08-02T00:42:38Z

This should be fixed now in the latest release. If you find that this is still occurring for you reopen the issue.

steve28 · 2020-08-02T01:29:19Z

This should be fixed now in the latest release. If you find that this is still occurring for you reopen the issue.

Does this require a certain version of HA?

zachowj · 2020-08-02T01:49:23Z

Does this require a certain version of HA?

No

zachowj added the bug Something isn't working label Jul 9, 2020

neilenns mentioned this issue Jul 27, 2020

Stuck at "connecting" after a reboot #255

Closed

zachowj closed this as completed in 93d396c Aug 1, 2020

DirkMu mentioned this issue Aug 2, 2020

Function node not working after HA reboot #257

Closed

mattmattmatt mentioned this issue Aug 29, 2020

HA nodes don't start "running" without redeploy of NR flows after HA restart #260

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

websocket connection being made before component loaded #250

websocket connection being made before component loaded #250

steve28 commented Jul 2, 2020

DirkMu commented Jul 3, 2020

bonanitech commented Jul 4, 2020 •

edited

Loading

bonanitech commented Jul 7, 2020 •

edited

Loading

zachowj commented Jul 9, 2020

bonanitech commented Jul 9, 2020

steve28 commented Jul 21, 2020

zachowj commented Jul 22, 2020 •

edited

Loading

zachowj commented Jul 23, 2020

steve28 commented Jul 23, 2020 •

edited

Loading

zachowj commented Jul 23, 2020

steve28 commented Jul 27, 2020 •

edited

Loading

zachowj commented Jul 29, 2020

zachowj commented Aug 2, 2020

steve28 commented Aug 2, 2020

zachowj commented Aug 2, 2020

websocket connection being made before component loaded #250

websocket connection being made before component loaded #250

Comments

steve28 commented Jul 2, 2020

Describe the bug

To Reproduce

Environment (please complete the following information):

Other (please complete the following information):

Additional context

DirkMu commented Jul 3, 2020

bonanitech commented Jul 4, 2020 • edited Loading

bonanitech commented Jul 7, 2020 • edited Loading

zachowj commented Jul 9, 2020

bonanitech commented Jul 9, 2020

steve28 commented Jul 21, 2020

zachowj commented Jul 22, 2020 • edited Loading

zachowj commented Jul 23, 2020

steve28 commented Jul 23, 2020 • edited Loading

zachowj commented Jul 23, 2020

steve28 commented Jul 27, 2020 • edited Loading

zachowj commented Jul 29, 2020

zachowj commented Aug 2, 2020

steve28 commented Aug 2, 2020

zachowj commented Aug 2, 2020

bonanitech commented Jul 4, 2020 •

edited

Loading

bonanitech commented Jul 7, 2020 •

edited

Loading

zachowj commented Jul 22, 2020 •

edited

Loading

steve28 commented Jul 23, 2020 •

edited

Loading

steve28 commented Jul 27, 2020 •

edited

Loading