Z-Wave JS - entities disappear if zwave-js server restarts

[steve28]

The problem

When the zwave-js server restarts, some entities in Home Assistant disappear. In addition, the "reload" menu option for the configuration also disappears, thus requiring a restart of HA to get everything back.

What is version of Home Assistant Core has the issue?

2021.2.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Z-Wave JS

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zwave_js

Example YAML snippet

N/A

Anything in the logs that might be useful for us?

N/A

Tagging @jcam per request

[jcam]

I also experience this, I am using HASS OS with a zwavejs2mqtt add-on.
Will try to gather logs tonight

[probot-home-assistant]

Hey there @home-assistant/z-wave, mind taking a look at this issue as its been labeled with an integration (zwave_js) you are listed as a codeowner for? Thanks!
_{^{(message by CodeOwnersMention)}}

[steve28]

As additional information, I am running the zwavejs2mqtt docker container with mqtt/gateway disabled

[MartinHjelmare]

When the server restarts the integration will be reloaded. Currently that means the entities will be removed and then re-added when the server reports the corresponding nodes and values. So this is expected behavior currently.

There's an improvement in progress that will turn the entities unavailable instead of removing them when the integration is reloaded.

[jcam]

They should come back though, when the server reports them ready. What we are experiencing is that they don't come back, the integration doesn't attempt to reload, and the reload option is missing.

[marcelveldt]

hmmm, I wonder if there's a difference between official Z-Wave server add-on and zwavejs2mqtt.
Maybe the zwavejs2mqtt doesn't restart the server cleanly when the addon/docker container is restarted.

Even if that's the case, the heartbeat built-in to aiohttp should kick in after 55 seconds.
Did you wait a few minutes to see if it detects the lost connection ?

[jcam]

I've tried giving it an hour or so...

[jcam]

Just tried to grab logs. My laptop version (which is older) grabbed tons of logs but also worked just fine.
The one that runs on my nuc device:

2021-02-08 07:41:28 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Z-Wave JS for zwave_js             
Traceback (most recent call last):                                                                                              
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 239, in async_setup                                       
    result = await component.async_setup_entry(hass, self)  # type: ignore                                                      
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/__init__.py", line 182, in async_setup_entry                   
    await client.connect()                                                                                                      
  File "/usr/local/lib/python3.8/site-packages/zwave_js_server/client.py", line 81, in connect                                  
    await self._client.receive_json()                                                                                           
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client_ws.py", line 291, in receive_json                                 
    data = await self.receive_str(timeout=timeout)                                                                              
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client_ws.py", line 276, in receive_str                                     
    raise TypeError(f"Received message {msg.type}:{msg.data!r} is not str")                                  
TypeError: Received message 257:None is not str   

[jcam]

I noticed in the zwavejs2mqtt control panel, the home ID and home hex were blank during the first few stages of the interview. could be related, or could be unrelated.

[jcam]

Updated my laptop version to 2021.2.1, got the same thing:

2021-02-08 07:52:02 DEBUG (MainThread) [zwave_js_server] Listen completed. Cleaning up
2021-02-08 07:52:02 INFO (MainThread) [homeassistant.components.zwave_js] Disconnected from server. Reloading integration
2021-02-08 07:52:02 DEBUG (MainThread) [zwave_js_server] Trying to connect
2021-02-08 07:52:02 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Z-Wave JS' for zwave_js integration not ready yet. Retrying in 5 seconds
2021-02-08 07:52:07 DEBUG (MainThread) [zwave_js_server] Trying to connect
2021-02-08 07:52:08 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Z-Wave JS for zwave_js
Traceback (most recent call last):
  File "/prs/zwave/core/homeassistant/config_entries.py", line 239, in async_setup
    result = await component.async_setup_entry(hass, self)  # type: ignore
  File "/prs/zwave/core/homeassistant/components/zwave_js/__init__.py", line 182, in async_setup_entry
    await client.connect()
  File "/prs/zwave/core/venv/lib/python3.9/site-packages/zwave_js_server/client.py", line 81, in connect
    await self._client.receive_json()
  File "/prs/zwave/core/venv/lib/python3.9/site-packages/aiohttp/client_ws.py", line 291, in receive_json
    data = await self.receive_str(timeout=timeout)
  File "/prs/zwave/core/venv/lib/python3.9/site-packages/aiohttp/client_ws.py", line 276, in receive_str
    raise TypeError(f"Received message {msg.type}:{msg.data!r} is not str")
TypeError: Received message 257:None is not str

[marcelveldt]

I noticed in the zwavejs2mqtt control panel, the home ID and home hex were blank during the first few stages of the interview. could be related, or could be unrelated.

That's what I expected. This is a race condition. The reconnect happens when the server is just not ready yet and thus we get unexpected results. We should guard the code that we only continue if all expecting objects are present and else consider it not yet ready.

[jcam]

Besides the home id, what else should be included in such a guard?

I see you're already checking for server version here https://github.com/home-assistant-libs/zwave-js-server-python/blob/master/zwave_js_server/client.py#L93

[MartinHjelmare]

@marcelveldt Does the server need updating to solve the TypeError?

[marcelveldt]

@marcelveldt Does the server need updating to solve the TypeError?

No, the server just dumps whatever is (already) there. What I suspect is that we just a get a partial dump if the above happens. So maybe we should check for a few properties to exist before assuming the connection is successful.
Looking at the above error, we seem to retrieve a malformed message (so not even an incomplete one).

From everything I read above, the python lib connects to the server just before it is even ready to dump something and will throw an error OR incomplete dump.

[MartinHjelmare]

Line 81 in the stack trace is still inside the Python client connect method. We don't have any data yet from the server at that point.

[rccoleman]

Same/similar thing here with 2021.2.2 after restarting my custom zwjs2mqtt container:

2021-02-08 17:04:23 DEBUG (MainThread) [zwave_js_server] Listen completed. Cleaning up
2021-02-08 17:04:23 INFO (MainThread) [homeassistant.components.zwave_js] Disconnected from server. Reloading integration
2021-02-08 17:04:23 DEBUG (MainThread) [zwave_js_server] Trying to connect
2021-02-08 17:04:24 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Z-Wave JS' for zwave_js integration not ready yet. Retrying in 5 seconds
2021-02-08 17:04:29 DEBUG (MainThread) [zwave_js_server] Trying to connect
2021-02-08 17:04:29 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Z-Wave JS for zwave_js
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 239, in async_setup
    result = await component.async_setup_entry(hass, self)  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/__init__.py", line 182, in async_setup_entry
    await client.connect()
  File "/usr/local/lib/python3.8/site-packages/zwave_js_server/client.py", line 81, in connect
    await self._client.receive_json()
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client_ws.py", line 291, in receive_json
    data = await self.receive_str(timeout=timeout)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/client_ws.py", line 276, in receive_str
    raise TypeError(f"Received message {msg.type}:{msg.data!r} is not str")
TypeError: Received message 257:None is not str
2021-02-08 17:11:11 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139856284059392] Error handling message: Unknown error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/connection.py", line 95, in async_handle
    handler(self.hass, self, schema(msg))
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/decorators.py", line 50, in with_admin
    func(hass, connection, msg)
  File "/usr/src/homeassistant/homeassistant/components/zwave_js/api.py", line 50, in websocket_network_status
    client = hass.data[DOMAIN][entry_id][DATA_CLIENT]
KeyError: 'bc9765f242063d943b466eccfa2fbcdd'

Had to restart HA to get the network up and running, after which is was fine.