[SOLVED] Z-Wave unreliable in 2.5.0.M4

rrgeorge · October 24, 2019, 1:57pm

Hi,

It seems that something has changed in the Z-Wave binding since at least 2.5.0.M3. I noticed that in 2.5.0.M3 devices would randomly go offline without explanation, and would only come back after I manually performed a network sync. Every most devices would go offline, and when I’d wake up in the morning my z-wave light bulbs will be turned on, and openhab would say they’re offline. So I rolled back to 2.5.0.M1, and have had no issue for weeks. Yesterday, I saw that 2.5.0.M4 had been released, so I updated my system to see if this issue has been fixed. It has not. I noticed after a few hours, one (little used) device went offline but I figured it was an isolated instance because everything else appeared to be working. This morning I woke up to find my bulbs turned on, and offline like before. I check openHAB, and a bunch of my devices are marked offline again. Now, I’ve tried to search for this issue before and I couldn’t quite find something similar… I would like to try to resolve this issue, rather than forever being stuck at 2.5.0.M1, so if any one has any idea what could be going on, I’d love some input.

Celaeno1 · October 24, 2019, 2:05pm

Do you really mean 2.4.0.M4? Or do you mean 2.5.0.M4 ?

2.4.0.M4 was released on 25 Sep 2018.
2.5.0.M4 was released on 20 Oct 2019.

Bruce_Osborne · October 24, 2019, 2:14pm

Also, 2.5M4 has been stable for me as was 2.5M3. There were some snapshots that had z-wave binding issues but that has been resolved for about a week or so.

Celaeno1 · October 24, 2019, 2:16pm

Do you excatly know since which snapshot it has been resolved? Before or after 1731?

rrgeorge · October 24, 2019, 2:17pm

Whoops. Yes, I meant 2.5.0… I have edited my original post. Thanks.

Bruce_Osborne · October 24, 2019, 2:22pm

Not sure. Here is the PR that fixed it.

rrgeorge · October 24, 2019, 2:31pm

It seems to all be related to the daily network heal (currently configured for 2AM)

2019-10-24 02:37:27.380 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node23' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.387 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node3' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.395 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node28' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.402 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node17' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.409 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node16' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.416 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.423 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node14' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.434 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node9' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.441 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node7' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:27.448 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node6' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:37:52.520 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2019-10-24 02:38:00.237 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:38:22.520 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2019-10-24 02:38:31.795 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:38:52.520 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2019-10-24 02:39:30.853 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
2019-10-24 02:39:53.039 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node15' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2019-10-24 02:39:59.080 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:d662a132:node9' has been updated.
2019-10-24 02:40:02.111 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:d662a132:node9' has been updated.
2019-10-24 02:40:02.114 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node9' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2019-10-24 02:40:05.049 [hingStatusInfoChangedEvent] - 'zwave:device:d662a132:node14' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE

Bruce_Osborne · October 24, 2019, 2:34pm

Any phantom or ghost nodes in the network? Devices trying to route through non-existent nodes can cause many random network issues. The bad nodes need to be removed from the Z-Wave controller to resolve this.

I have one node doing this now for me but I think my issue is marginal W-Wave signal at that location. Mains powered nodes or repeaters can help resolve issues like that,

Celaeno1 · October 24, 2019, 2:35pm

It was fixed on 17 Oct 2019. Snapshot 1731 was released on 20 Oct 2019.

Having a similar (or the same?) problem, so it’s not fixed.

Bruce_Osborne · October 24, 2019, 2:37pm

Please open an issue on GitHub then. That is how the PR I linked to finally got resolved. Chris is extra busy right now with Zigbee and posting on GitHub lets other developers try to help.

Celaeno1 · October 24, 2019, 2:42pm

I have the SAME issue!

rrgeorge · October 24, 2019, 2:52pm

Nope.

All of the affected devices are mains powered.

Celaeno1 · October 24, 2019, 2:53pm

Mine are battery powered…

See also this topic.

Celaeno1 · October 24, 2019, 3:00pm

I’ll do further investigations (when I’m back from work ) . After that I’ll open an issue on GitHub.

Bruce_Osborne · October 24, 2019, 3:06pm

The one device giving me headaches at healing is mains powered.

rrgeorge · October 24, 2019, 3:09pm

Correction, 1 of them is battery powered.

ariela · October 24, 2019, 3:56pm

I have 19 zwave devices with openHAB 2.5.0~S1733-1 (Build #1733), no issues at all till now. May I ask you to explain a bit more?

Andrea

rrgeorge · October 24, 2019, 4:00pm

You got me thinking about this, so I investigated further, and found 1 device that I couldn’t get to respond properly. I tried to mark it as failed and remove it, and I kept getting errors, I eventually had to restart the ZWave binding to get it to remove the old node:

2019-10-24 08:13:42.645 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:d662a132:node8' to inbox.
2019-10-24 08:13:59.308 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node not placed on stack due to error 0x18.
2019-10-24 08:13:59.572 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node not placed on stack due to error 0x18.
2019-10-24 08:13:59.834 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node not placed on stack due to error 0x18.
2019-10-24 08:15:30.257 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:d662a132:node8' to inbox.
2019-10-24 08:17:06.254 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node returned with response 0x3.
2019-10-24 08:17:43.762 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:17:44.021 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:17:44.283 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:27:07.726 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:d662a132:node29' to inbox.
2019-10-24 08:27:20.161 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 29: Command Class COMMAND_CLASS_BASIC has version 0!
2019-10-24 08:30:11.240 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node returned with response 0x3.
2019-10-24 08:32:31.994 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:32:32.252 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:32:32.514 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:03.360 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:03.619 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:03.880 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:13.392 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:13.644 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:13.903 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:33:14.161 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:33:14.420 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:33:14.683 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:33:23.950 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:33:24.467 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:33:24.722 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 8: Remove failed node failed as Controller Busy!
2019-10-24 08:37:28.591 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:37:28.851 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!
2019-10-24 08:37:29.108 [ERROR] [essage.ReplaceFailedNodeMessageClass] - NODE 8: Replace failed node failed as Controller Busy!

I have also set my network to heal at 9 am to see if this resolves the issue.

ariela · October 24, 2019, 4:03pm

sometimes it’s useful also to remove the device from the USB key. What controller are you using btw?

Another thing to do:

stop openhab
remove the file with the zwave node in the name in the zwave folder (/var/lib/openhab2/zwave) -> something like network_xxxxxxxxxx__node_8.xml
start openhab of course

Bruce_Osborne · October 24, 2019, 4:08pm

The Z-Wave network is stored on the controller. Deleting the xml file achieves nothing useful. I have put my USB controller on a Windows box & used Zensys Tools to delete phantom nodes.

I now suspect I have dome phantom nodes and will likely try OpenZWave Control Panel on Linux, with OpenHAB shut down.