Most Z-wave Light Switched Dead All of A Sudden

firstof9 · December 28, 2019, 6:52pm

Is your stick directly into the USB port or on a USB extender?

William_Rodriguez · December 28, 2019, 6:59pm

its on an extender, I tried different ports but no luck. Haven’t tried it out without the extender yet, guess I can do that next.

firstof9 · December 28, 2019, 7:02pm

Before removing the extender, check your OZW_Log.txt for things like problems sending command to node01 (the stick) or a lot of NACKS.

William_Rodriguez · December 28, 2019, 7:56pm

These are several of the errors found in the log

2019-12-28 09:35:50.961 Info, Controller Does not Support SUC - Cannot Setup Controller as SUC Node

2019-12-28 09:35:51.094 Info, Value size is invalid. Only 1, 2 & 4 supported for node 33, class 0x33, instance 1, index 1

2019-12-28 09:36:06.205 Info, Node002, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-12-28 09:36:06.205 Info, Node002,   Node 2 has been marked as asleep

2019-12-28 09:37:21.953 Detail, Node048, Notification: Notification - NoOperation

2019-12-28 09:37:24.547 Info, Node003, WARNING: ZW_DELETE_RETURN_ROUTE failed. No ACK received - device may be asleep.
2019-12-28 09:37:24.547 Warning, Node003, WARNING: Device is not a sleeping node.

2019-12-28 09:37:24.547 Detail, Notification: ControllerCommand - Failed

2019-12-28 09:38:09.116 Info, Node023, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2019-12-28 09:38:09.116 Warning, Node023, WARNING: Device is not a sleeping node.
2019-12-28 09:38:09.116 Error, Node023, ERROR: node presumed dead
2019-12-28 09:38:09.116 Warning, CheckCompletedNodeQueries m_allNodesQueried=0 m_awakeNodesQueried=0
2019-12-28 09:38:09.116 Warning, CheckCompletedNodeQueries all=0, deadFound=1 sleepingOnly=0
2019-12-28 09:38:09.116 Detail, Node001,   Expected callbackId was received
2019-12-28 09:38:09.116 Detail, Node023, Notification: Notification - Node Dead
2019-12-28 09:38:14.174 Error, Node023, ERROR: Dropping command because node is presumed dead
2019-12-28 09:38:14.174 Detail, Node023, Removing current message
2019-12-28 09:38:14.174 Detail, Node023, Notification: Notification - TimeOut
2019-12-28 09:38:14.183 Error, Node023, ERROR: Dropping command because node is presumed dead
2019-12-28 09:38:14.183 Detail, Node023, Removing current message
2019-12-28 09:38:14.183 Error, Node023, ERROR: Dropping command because node is presumed dead
2019-12-28 09:38:14.183 Detail, Node023, Removing current message
2019-12-28 09:38:14.183 Error, Node023, ERROR: Dropping command because node is presumed dead
2019-12-28 09:38:14.183 Detail, Node023, Removing current message
2019-12-28 09:38:14.183 Error, Node023, ERROR: Dropping command because node is presumed dead
2019-12-28 09:38:14.183 Detail, Node023, Removing current message
2019-12-28 09:38:14.183 Detail,

2019-12-28 11:06:18.044 Error, Node023, WARNING: node revived
2019-12-28 11:06:18.044 Detail, Node023, AdvanceQueries queryPending=0 queryRetries=0 queryStage=CacheLoad live=1
2019-12-28 11:06:18.044 Detail, Node023, QueryStage_CacheLoad
2019-12-28 11:06:18.044 Info, Node023, Node Identity Codes: 027a:b112:1f1c
2019-12-28 11:06:18.044 Info, Node023, NoOperation::Set - Routing=true
2019-12-28 11:06:18.044 Detail, Node023, Queuing (NoOp) NoOperation_Set (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x00, 0x00, 0x25, 0x55, 0x80
2019-12-28 11:06:18.044 Detail, Node023, Queuing (Query) Query Stage Complete (CacheLoad)
2019-12-28 11:06:18.044 Info, Node023, Received Basic report from node 23: level=88
2019-12-28 11:06:18.044 Detail, Node023, Notification: Notification - Node Alive
2019-12-28 11:06:18.048 Detail, 
2019-12-28 11:06:18.048 Info, Node023, Sending (NoOp) message (Callback ID=0x55, Expected Reply=0x13) - NoOperation_Set (Node=23): 0x01, 0x09, 0x00, 0x13, 0x17, 0x02, 0x00, 0x00, 0x25, 0x55, 0x80
2019-12-28 11:06:18.054 Detail, Node023,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-12-28 11:06:18.054 Detail, Node023,   ZW_SEND_DATA delivered to Z-Wave stack
2019-12-28 11:06:18.172 Detail, Node023,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x17, 0x05, 0x26, 0x03, 0x58, 0x58, 0x00, 0xc7 ```

firstof9 · December 28, 2019, 7:59pm

Try running your full log file thru the openzwave analyzer:

http://openzwave.com/log-analyzer

but this is looking more and more like poor signal than anything else.

Petrica · December 28, 2019, 8:33pm

What is the size of the zwcfg_0xaaaaaaaa.xml file (aa…aa is an alphanumeric sequence; if running Hassio, then it would be in Config folder)?

If this is really small (a few B, not KB) you might need to restore the file from a previous version (shutdown HA, overwrite the file in Config folder, then start HA; you might need to start HA again from ssh as rebooting the server could write back the incorrect file).

firstof9 · December 28, 2019, 8:39pm

I’ve never see the cache xml cause dead nodes to occur only missing nodes.

William_Rodriguez · December 28, 2019, 8:47pm

I’m showing 2 of them, one 241 KB and the other is 981 bytes.
The larger one has a modified date and time of 12/27/2018 1:27 PM, the larger one has a modified date and time of 12/28/2019 9:22 AM.

my mistake, they were both modified in 2019, the month and date are correct.

By the way I’m running Home Assistant not Hassio.

Petrica · December 28, 2019, 9:01pm

Then it’s easier to control the server

I suggest making several copies (on a different computer, for good measure) of these two files prior to any testing.

There are two files probably because you changed the Z-Wave network key, or a major HA version needed to do this.

It is not clear when the larger one was modified (my guess is that the larger one was modified in 2018 and the smaller one in 2019 thus the one that is being currently loaded by HA is the smaller one, which is invalid). I think you might need an older working copy (several days before) of the file that is currently showing a small size. I’m unsure if renaming the other file in the config folder might work.

William_Rodriguez · December 28, 2019, 9:13pm

my mistake, they were both modified in 2019, the dates are correct.

I just replaced those two with 2 from a backup that I did on the 22nd. Lets see what happens next.

William_Rodriguez · December 28, 2019, 9:23pm

Well… After a reboot, everything is coming back on line, no dead nodes.

Hold on, I just found these errors on my log.

2019-12-28 15:11:08 ERROR (Dummy-8) [openzwave] Error in manager callback
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/openzwave/network.py", line 944, in zwcallback
    self._handle_node_removed(args)
  File "/usr/local/lib/python3.7/site-packages/openzwave/network.py", line 1250, in _handle_node_removed
    **{'network': self, 'node': node})
  File "/usr/local/lib/python3.7/site-packages/pydispatch/dispatcher.py", line 338, in send
    **named
  File "/usr/local/lib/python3.7/site-packages/pydispatch/robustapply.py", line 55, in robustApply
    return receiver(*arguments, **named)
  File "/usr/src/homeassistant/homeassistant/components/zwave/__init__.py", line 500, in node_removed
    entity = hass.data[DATA_DEVICES][node_key]
KeyError: 'node-45'
2019-12-28 15:11:38 WARNING (MainThread) [homeassistant.components.zwave] Z-Wave node 45 not ready after 30 seconds, continuing anyway
2019-12-28 15:11:38 WARNING (MainThread) [homeassistant.components.zwave] Z-Wave node 51 not ready after 30 seconds, continuing anyway

William_Rodriguez · December 28, 2019, 10:38pm

replacing the files seems to have done the trick. I upgraded back to 0.103.4 and all of the nodes are working again, no signs of dead nodes and Node 45 is gone.

@firstof9 & @Petrica thanks for the support, I would have never figured this out on my own.

Petrica · December 29, 2019, 10:23am

You’re welcome!