Z-Wave devices report "Node not communicating with controller", but they work anyhow

[RealBrianWarner (Brian Warner)]

Hi everyone,

I recently migrated from OH2.4 stable to OH2.5 stable by installing a fresh system. When I plugged in my Z-Stick, I rediscovered all of my devices. Then I upgraded my binding to the 2.5.6-20200612.215243-7 snapshot using @5iver’s script to get support for a device which I contributed to the database.

Now, for some reason, many of my devices are reporting “Node not communicating with controller” though they seem to be working. I can switch them on/off through PaperUI or HABpanel, and they briefly show Online. Shortly afterwards, they go back to “Not communicating”. Likewise, if I manually switch them on, they report their state back to the system, then go back to “Not communicating”.

I have about 70 devices in a robust config, and roughly 25 of them are in this state at a given time. Many, but not all, are mains powered.

I’ve had DEBUG level logging on the zwave binding for the past few days. Looking through the logs using @chris’s log viewer, I see a lot of “Neighbor update failed” and “message timeout” messages.

Here’s a sample from the log itself:

2020-06-15 03:40:53.724 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=83, payload=53 23 
2020-06-15 03:40:53.724 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: Got NodeNeighborUpdate request.
2020-06-15 03:40:53.724 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: NodeNeighborUpdate FAILED
2020-06-15 03:40:53.725 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveNetworkEvent
2020-06-15 03:40:53.725 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 4783: Transaction CANCELLED
2020-06-15 03:40:53.725 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: CANCEL while sending message. Requeueing - 2 attempts left!
2020-06-15 03:40:53.725 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 4783: Transaction RESET with 2 retries remaining.
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Added 4783 to queue - size 22
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-15 03:40:53.725 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 05 54 E3 
2020-06-15 03:40:53.725 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 05 54 E3 
2020-06-15 03:40:53.725 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 84
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: TID 4783: Transaction not completed
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-15 03:40:53.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-15 03:40:53.726 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 84
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-15 03:40:53.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-15 03:40:53.727 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 54 23 C5 
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=84, payload=54 23 
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=84, payload=54 23 
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 84
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 84
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 4783: (Callback 84)
2020-06-15 03:40:53.727 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-06-15 03:40:53.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 4783: callback 84
2020-06-15 03:40:53.728 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=84, payload=54 23 
2020-06-15 03:40:53.728 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: Got NodeNeighborUpdate request.
2020-06-15 03:40:53.728 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: NodeNeighborUpdate FAILED
2020-06-15 03:40:53.728 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveNetworkEvent
2020-06-15 03:40:53.728 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 4783: Transaction CANCELLED
2020-06-15 03:40:53.728 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: CANCEL while sending message. Requeueing - 1 attempts left!
2020-06-15 03:40:53.728 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 4783: Transaction RESET with 1 retries remaining.
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Added 4783 to queue - size 22
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-15 03:40:53.728 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 05 55 E2 
2020-06-15 03:40:53.728 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 05 55 E2 
2020-06-15 03:40:53.728 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: TID 4783: Transaction not completed
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-15 03:40:53.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-15 03:40:53.729 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-15 03:40:53.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-06-15 03:40:53.730 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 55 23 C4 
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=85, payload=55 23 
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=85, payload=55 23 
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 4783: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 4783: (Callback 85)
2020-06-15 03:40:53.730 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-06-15 03:40:53.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 4783: callback 85
2020-06-15 03:40:53.731 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=85, payload=55 23 
2020-06-15 03:40:53.731 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: Got NodeNeighborUpdate request.
2020-06-15 03:40:53.731 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 5: NodeNeighborUpdate FAILED
2020-06-15 03:40:53.731 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveNetworkEvent
2020-06-15 03:40:53.731 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 4783: Transaction CANCELLED
2020-06-15 03:40:53.731 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: Retry count exceeded. Discarding message: TID 4783: [CANCELLED] priority=Controller, requiresResponse=true, callback: 85
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: TID 4783: Transaction completed
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:4783 CANCELLED
2020-06-15 03:40:53.731 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-06-15 03:40:53.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 4783: Transaction event listener: DONE: CANCELLED -> 
2020-06-15 03:40:53.731 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@2eb75c3

Going back in the logs, I see this around the time of the network heal:

2020-06-15 02:00:53.683 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.683 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.683 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 1: Can not start heal as initialisation is not complete (UPDATE_NEIGHBORS).
2020-06-15 02:00:53.683 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.684 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 5: Can not start heal as initialisation is not complete (UPDATE_NEIGHBORS).
2020-06-15 02:00:53.684 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.684 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Can not start heal as initialisation is not complete (UPDATE_NEIGHBORS).
2020-06-15 02:00:53.684 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.684 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 7: Can not start heal as initialisation is not complete (DYNAMIC_VALUES).
2020-06-15 02:00:53.684 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.
2020-06-15 02:00:53.684 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 8: Can not start heal as initialisation is not complete (UPDATE_NEIGHBORS).
2020-06-15 02:00:53.684 [DEBUG] [enhab.binding.zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:f18426fd.

(It keeps going after that…)

I have a lot of log data. My system is set to heal at 2am. I’ve posted the attempted heal plus the next five minutes on pastebin, but have a lot more available.

Does anybody have any thoughts on what might be happening, or any ideas what would cause this? I see the neighbor update on node1 fails, which makes me wonder if maybe it’s a controller problem?

Thank you!

[Rafal (Rafal Lukawiecki)]

I have experienced something similar, but only with a couple of battery powered devices (Fibaro Flood Sensors). They ”worked” but were showing as not communicating with the controller. What turned out was that I had two issues. First of all, there were duplicates of those devices in the Z-Wave stick’s own internal database, which I had to remove.

Secondly, I had to change their wake-up interval to 3 hours (or more frequent) in order for them to complete the network heal. I do not understand why that was necessary with OH2.5, but it fixed the issue. Then I checked by increasing the interval to 4 hours and a day later they were back to showing as no longer communicating with the controller. Bringing back to 3 hours fixed the issue again.

Perhaps you have a completely different issue, but I thought sharing mine might help if you are clutching at straws…

[ljsquare (Laurens Jan Merkx)]

@Rafal

Secondly, I had to change their wake-up interval to 3 hours (or more frequent) in order for them to complete the network heal. I do not understand why that was necessary with OH2.5, but it fixed the issue.

Thanks for the tip. I’ve a similar problem with a powered (non-battery) device. I’ll give it a try

[RealBrianWarner (Brian Warner)]

I don’t really have a “Here’s how I fixed this with steps” for this one, but I can say that applying the most recent update to 2.5.6 stable and going back to the stock z-wave binding fixed everything. My reason for going to the snapshot binding was to get support for a device which I’d recently added to the database, so now it’s a moot point on both.

It’s been rock solid for a week now, so I’m going to close this thread and mark it solved.

[sintei (Nicke)]

How did you downgrade the zwave binding?
I have the same problem now.
After a couple of days different nodes start saying they cant communicate with the controller.
They work fine, but the more days go, they get slower in response and I have to reboot openhab.
I did not have this problem with 2.5.6 but it appeared in 2.5.10.

[chris (Chris Jackson)]

@sintei

How did you downgrade the zwave binding

You will need to find an older binding version and use that.

@sintei

I did not have this problem with 2.5.6 but it appeared in 2.5.10

There are no real changes between versions - just database updates - so I doubt there is a difference in the binding that will cause whatever problem you see.