ZWave Issues the last couple of weeks

Asmegin · April 12, 2019, 10:26am

Since the last few updates, my ZWave hasn’t been working very well. My devices stop working multiple times a day and a restart is required.

I constantly get these errors for all my devices:

Z-Wave Notification ValueChanged ({'homeId': 3896168056, 'nodeId': 14, 'commandClass': 'COMMAND_CLASS_SWITCH_BINARY', 'instance': 1, 'index': 0, 'id': 72057594277609472, 'genre': 'User', 'type': 'Bool', 'value': True, 'label': 'Switch', 'units': '', 'readOnly': False}) for an unknown node 14

The UI will stop updating with the lights actual status and switching it in HA won’t do anything (toggle switches and then turns back off).

2019-04-12 06:12:36.908 Info, Node014, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2019-04-12 06:12:36.908 Info, Node014, SwitchBinary::Set - Setting node 14 to On
2019-04-12 06:12:36.908 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0xff, 0x25, 0x8b, 0x9e
2019-04-12 06:12:36.908 Detail, Node014, Queuing (Send) SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0x8c, 0x67
2019-04-12 06:12:36.908 Detail,
2019-04-12 06:12:36.908 Info, Node014, Sending (Send) message (Callback ID=0x8b, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=14): 0x01, 0x0a, 0x00, 0x13, 0x0e, 0x03, 0x25, 0x01, 0xff, 0x25, 0x8b, 0x9e
2019-04-12 06:12:36.916 Detail, Node014,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-04-12 06:12:36.916 Detail, Node014,   ZW_SEND_DATA delivered to Z-Wave stack
2019-04-12 06:12:36.936 Detail, Node014,   Received: 0x01, 0x18, 0x00, 0x13, 0x8b, 0x00, 0x00, 0x02, 0x00, 0xbe, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0xc2
2019-04-12 06:12:36.936 Detail, Node014,   ZW_SEND_DATA Request with callback ID 0x8b received (expected 0x8b)
2019-04-12 06:12:36.936 Info, Node014, Request RTT 27 Average Request RTT 27
2019-04-12 06:12:36.936 Detail,   Expected callbackId was received
2019-04-12 06:12:36.936 Detail,   Expected reply was received
2019-04-12 06:12:36.936 Detail,   Message transaction complete
2019-04-12 06:12:36.936 Detail,
2019-04-12 06:12:36.936 Detail, Node014, Removing current message
2019-04-12 06:12:36.936 Detail,
2019-04-12 06:12:36.936 Info, Node014, Sending (Send) message (Callback ID=0x8c, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=14): 0x01, 0x09, 0x00, 0x13, 0x0e, 0x02, 0x25, 0x02, 0x25, 0x8c, 0x67
2019-04-12 06:12:36.943 Detail, Node014,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-04-12 06:12:36.944 Detail, Node014,   ZW_SEND_DATA delivered to Z-Wave stack
2019-04-12 06:12:36.963 Detail, Node014,   Received: 0x01, 0x18, 0x00, 0x13, 0x8c, 0x00, 0x00, 0x02, 0x00, 0xbf, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0xc4
2019-04-12 06:12:36.963 Detail, Node014,   ZW_SEND_DATA Request with callback ID 0x8c received (expected 0x8c)
2019-04-12 06:12:36.963 Info, Node014, Request RTT 27 Average Request RTT 27
2019-04-12 06:12:36.963 Detail,   Expected callbackId was received
2019-04-12 06:12:36.980 Detail, Node014,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x0e, 0x03, 0x25, 0x03, 0xff, 0xbf, 0x00, 0x9b
2019-04-12 06:12:36.980 Detail,
2019-04-12 06:12:36.980 Info, Node014, Response RTT 44 Average Response RTT 44
2019-04-12 06:12:36.980 Info, Node014, Received SwitchBinary report from node 14: level=On
2019-04-12 06:12:36.980 Detail, Node014, Refreshed Value: old value=true, new value=true, type=bool
2019-04-12 06:12:36.980 Detail, Node014, Changes to this value are not verified
2019-04-12 06:12:36.980 Detail, Node014,   Expected reply and command class was received
2019-04-12 06:12:36.980 Detail, Node014,   Message transaction complete
2019-04-12 06:12:36.980 Detail,
2019-04-12 06:12:36.980 Detail, Node014, Removing current message
2019-04-12 06:12:36.980 Detail, Node014, Notification: ValueChanged

Any attempts to heal/test node result in ‘Fail to call service…’ and the following error:

14
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/websocket_api/commands.py", line 122, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1138, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.7/site-packages/homeassistant/core.py", line 1162, in _execute_service
    await self._hass.async_add_executor_job(handler.func, service_call)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/zwave/__init__.py", line 649, in heal_node
    node = network.nodes[node_id]
KeyError: 14

Also get this error:

Error in manager callback
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/openzwave/network.py", line 978, in zwcallback
    self._handle_node_queries_complete(args)
  File "/usr/local/lib/python3.7/site-packages/openzwave/network.py", line 1285, in _handle_node_queries_complete
    self.nodes[args['nodeId']].is_ready = True
KeyError: 1

It seems all my hardwired devices (Zooz, Inovelli, GE) are Initializing (CacheLoad), while my battery powered devices are Complete. Maybe because they’re asleep?

Hardware:
Intel Nuc
Hassio w/ docker
Zooz Zwave (basically an Aeotec)

wrkn · April 17, 2019, 5:20pm

Hello! I have had similar issues with the same setup: Zooz ZST10 stick, NUC, Hassio/docker on Ubuntu 18.04. Currently running HA 0.91.3. I haven’t had time to post yet for help, but some clues that make me think it’s not specifically Z-Wave but actually Hassio + USB not playing well. I first noticed it with 0.91.0 upgrade but it could have been happening more intermittently even earlier than that.

I unlinked (using Remove Node) everything, confirming through the OZW log, and decided to start over. This time watching the log closely. Here are OZW logs from just adding the stick (no nodes added yet) and a few subsequent restarts of HA:

Log 1 (fresh Z-Wave integration, add Zooz stick)
Log 2 (restarts)
Log 3
Log 4
Log 5

In sum, I’m seeing initialization errors that according to this thread seem to suggest that something is getting in the way of the HA <-> Z-Wave USB stick connection.

I also have the NUT, Node-RED, and SSH/Web Terminal addons running. In particular, NUT is losing the USB connection to my CyberPower UPS every other day on average. I have to restart the addon to recover from it. I’m mentioning Node-RED and SSH/Web Terminal because I know Hassio gives those addons a full list of serial devices and maybe they are doing something.

I’m a novice with docker but I’d really like to know what next steps I can take to diagnose the issue. Also, is there a way to explicitly limit access to USB to a single Hassio container, e.g. only HA container is allowed to use the Z-Wave stick, only NUT can use the UPS?

petro · April 18, 2019, 4:01pm

Not having any issues, but I don’t have a zooz stick. Running aeon labs stick w/ nuc & hassio. Seems like the common issue is the zooz stick?

ramdisk · April 21, 2019, 2:58pm

Me too…it’s been hard to bring up my zwave network, mult reboots and restarts doesn’t work

petro · April 21, 2019, 3:09pm

I spoke too soon. Got a key error on a restart today. Cleared up after a subsequent restart.

wrkn · April 21, 2019, 3:10pm

After trying an Aeotec stick with same bad results, I figured out at least part of the problem. My Anker powered USB hub was misbehaving. After eliminating that from my setup, my UPS hasn’t lost connection. And the Zooz stick is working flawlessly so far (only two nodes re-added). Also I’m taking advice seen elsewhere to keep the zwave stick in the yellow USB port to ensure sufficient power.

silfa718 · May 1, 2019, 1:00am

Lost all my nodes after a restart today. Running an aeotec stick on NUC.

wrkn · May 1, 2019, 1:32am

IME every once in a while during HA restart the OZW initialization of the stick fails. This was happening almost 100% of the time when I had a misbehaving USB hub on the NUC. After throwing that in the trash, I’d say that 90% of my restarts work fine. When Z-Wave doesn’t initialize properly, I just restart again and that usually takes care of it.

I figured it out by just disconnecting all USB devices and then adding back one by one and restarting HA each time, watching the OZW log.

petro · May 5, 2019, 11:06am

Yep, i’d agree with this. 1/10 restarts and the zwave network starts incorrectly and your logs will be filled with errors. Restart and it goes away.

palengh · September 12, 2019, 12:37pm

I am experiencing the same issue: All hardwired items seem to work, those on battery fail to connect.

I was running Home Assistant 0.98.4, and upgraded to 0.98.5 today only to get the same errors as before. Here is the log after upgrading Hassio.

I am not very satisfied right now, as I have no clue where to start fixing this. The logs seem odd, as the connected wire powered entities kind of proofs the Z-wave stick and connected services seem to work.
@petro: You had any luck with this?
Several restarts do not seem to have any effect.

2019-09-12 12:40:55.100 Always, OpenZwave Version 1.4.3440 Starting Up
2019-09-12 12:41:23.233 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-09-12 12:41:23.234 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-09-12 12:41:23.234 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-09-12 12:41:23.234 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-09-12 12:41:23.234 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-09-12 12:41:23.240 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2019-09-12 12:41:23.241 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2019-09-12 12:41:23.247 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xe195d6db.  Our node ID = 1
2019-09-12 12:41:23.247 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2019-09-12 12:41:23.253 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2019-09-12 12:41:23.260 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2019-09-12 12:41:23.261 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2019-09-12 12:41:23.265 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2019-09-12 12:41:23.328 Info, contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2019-09-12 12:41:38.371 Info, Node001, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2019-09-12 12:41:38.383 Detail, Node002,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:41:38.404 Detail, Node002,   ZW_SEND_DATA Request with callback ID 0x0a received (expected 0x0a)
2019-09-12 12:41:38.417 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:41:49.673 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:41:49.680 Error, Node006, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:41:52.555 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x1f received (expected 0x1f)
2019-09-12 12:41:52.555 Info, Node006, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:41:52.571 Detail, Node007,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:04.733 Error, Node013, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:04.738 Error, Node013, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:04.745 Error, Node013, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:05.132 Detail, Node013,   ZW_SEND_DATA Request with callback ID 0x22 received (expected 0x22)
2019-09-12 12:42:05.132 Info, Node013, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:42:05.145 Detail, Node014,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:14.680 Detail, Node014,   ZW_SEND_DATA Request with callback ID 0x12 received (expected 0x12)
2019-09-12 12:42:14.680 Info, Node014, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:42:15.584 Detail, Node015,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:21.605 Detail, Node015,   ZW_SEND_DATA Request with callback ID 0x13 received (expected 0x13)
2019-09-12 12:42:21.605 Info, Node015, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:42:27.865 Detail, Node016,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:32.064 Error, Node017, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:47.254 Error, Node023, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:47.264 Error, Node023, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:47.274 Error, Node025, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2019-09-12 12:42:47.366 Detail, Node025,   ZW_SEND_DATA Request with callback ID 0x1c received (expected 0x1c)
2019-09-12 12:42:47.366 Info, Node025, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:42:47.386 Detail, Node027,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:48.594 Detail, Node027,   ZW_SEND_DATA Request with callback ID 0x1d received (expected 0x1d)
2019-09-12 12:42:48.624 Detail, Node028,   ZW_SEND_DATA delivered to Z-Wave stack
2019-09-12 12:42:56.699 Detail, Node028,   ZW_SEND_DATA Request with callback ID 0x1e received (expected 0x1e)
2019-09-12 12:42:56.699 Info, Node028, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-09-12 12:42:56.713 Info, Node002, Received reply to FUNC_ID_ZW_DELETE_RETURN_ROUTE - command in progress
2019-09-12 12:42:57.771 Info, Node002, Received reply to FUNC_ID_ZW_DELETE_RETURN_ROUTE for node 2 - SUCCESS
2019-09-12 12:42:58.054 Info, Node002, Received reply to FUNC_ID_ZW_ASSIGN_RETURN_ROUTE - command in progress
2019-09-12 12:42:58.542 Info, Node002, Received reply to FUNC_ID_ZW_ASSIGN_RETURN_ROUTE for node 2 - SUCCESS
2019-09-12 12:42:59.418 Info, Node005, Received reply to FUNC_ID_ZW_DELETE_RETURN_ROUTE - command in progress
2019-09-12 12:43:03.417 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x1e received (expected 0x2a)

2019-09-12 14:22:19.335 Info, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2019-09-12 14:22:19.335 Info,     Node 001 - Known
2019-09-12 14:22:19.335 Info,     Node 002 - Known
2019-09-12 14:22:19.335 Info,     Node 004 - Known
2019-09-12 14:22:19.335 Info,     Node 005 - Known
2019-09-12 14:22:19.335 Info,     Node 006 - Known
2019-09-12 14:22:19.335 Info,     Node 007 - Known
2019-09-12 14:22:19.335 Info,     Node 008 - Known
2019-09-12 14:22:19.336 Info,     Node 012 - Known
2019-09-12 14:22:19.336 Info,     Node 013 - Known
2019-09-12 14:22:19.336 Info,     Node 014 - Known
2019-09-12 14:22:19.336 Info,     Node 015 - Known
2019-09-12 14:22:19.336 Info,     Node 016 - Known
2019-09-12 14:22:19.336 Info,     Node 017 - Known
2019-09-12 14:22:19.336 Info,     Node 018 - Known
2019-09-12 14:22:19.336 Info,     Node 019 - Known
2019-09-12 14:22:19.336 Info,     Node 020 - Known
2019-09-12 14:22:19.336 Info,     Node 021 - Known
2019-09-12 14:22:19.336 Info,     Node 022 - Known
2019-09-12 14:22:19.336 Info,     Node 023 - Known
2019-09-12 14:22:19.336 Info,     Node 025 - Known
2019-09-12 14:22:19.336 Info,     Node 027 - Known
2019-09-12 14:22:19.336 Info,     Node 028 - Known

Markus99 · September 12, 2019, 1:19pm

Following.

Currently using SmartThing for ZWave and hesitant to move away. Would love to, but restarting the entire ZWave network (have ~30 devices) every time I need to restart HA seems like a lot of extra hassle. With ST it’s just ‘there’ when HA restarts w/out having to restart the entire ZWave mesh network…

I do have an Aeotec stick and a single device connected to it (for some reason my modem / Google WiFi puck sometimes lose their gigabit connection and drop to 100k. Built an automation that checks speed test results will turn off, wait 60 seconds, turn on the Google WiFi puck [using the zwave outlet connected to it and attached to the NUC/HA/Aeotec] in order to reset their connection).

I too notice that a small % (5-10%) of the time after restart ZWave doesn’t setup correctly, though a subsequent restart does clear that up. Supposed one could build an automation that waits XX seconds/minutes after HA starts and force a reboot if certain device(s) aren’t found / setup.

Anyhow… Trying very hard to ‘sit on my hands’ and take the ‘if it’s not broke don’t fix it approach’ to this currently less-than-ideal-NON-problem of running ST…

palengh · September 12, 2019, 1:25pm

So maybe I should look into an easy solution to this…
A; Using my left-over Raspberry PI as gateway
B; Buying an external Z-wave gateway like your SmartThings

How are these connected to the Home Assistant installation?

Markus99 · September 12, 2019, 1:31pm

Unsure how A would work (I’m not that technical).

B is a out-of-the-box HA integration - https://www.home-assistant.io/components/smartthings/

petro · September 12, 2019, 1:45pm

Your issue is different than mine. My issue would only rear it’s head 1 every 10 restarts. I’ve restarted about 15 times in the last 2 days and never hit the issue.

This is over exaggerated. As I said before, these errors rarely occur. And the solution is to restart HA, not the zwave network.

phantomdarkness · September 12, 2019, 1:47pm

I run a separate zwave-only instance of HASS that’s connected to my main instance via MQTT. There’s also zwave2mqtt and another solution that’s based on websockets. So there are options available.

Markus99 · September 12, 2019, 1:54pm

As mentioned, I’m far from an expert…

By restarting HA, does this not (because ZWave stick is attached) also then restart ZWave network?

petro · September 12, 2019, 1:55pm

Yes it does, but I don’t believe the issue is with open zwave. I believe the issue is with the communication between open zwave and HA, so restarting the network without restarting HA would not solve the issue. Although I haven’t ever tried it, it’s just an educated guess. The errors occur in the HA logs, and they are python errors. The errors also appear inside the HA code, not in the OZW code.

wrkn · February 8, 2020, 9:03pm

For posterity, I’ve 100% resolved my Zwave startup reliability issues on NUC/Docker/Hass.io setup by disabling & removing ModemManager. See https://www.home-assistant.io/hassio/installation/#debianubuntu

qoheleth · May 20, 2021, 11:59pm

I’m in the same boat here. I’ve bought a Nortek QuckStick HUSBZB-1 Combo ZWave and Zigbee controller, but each time the system boots (running a VM HA install on a SFF PC), I have to pull the stick and plug it back in after the booting is done. I’m not sure if there’s a way to make USB initialize before the batch file that starts my VM runs or even if that indeed is the problem.
So I’m reluctant to switch over from SmartThings which has always been reliable about starting up after a power failure or on the rare occasion when I reboot the hub. However, I note that some of my ZWave devices are “cloud” executed and I’d like to move to local execution.
I notice that Sonoff has a separate Zigbee hub and I’m wondering if anyone has used these and can verify that they’re reliable on restart. I can’t find a comparable ZWave hub though.
So, any ideas on making the USB stick initialize properly or alternative hubs that are locally managed would be helpful.