Zwave after heal: Node is not communicating with controller

roy_liao · August 20, 2019, 8:30pm

Hi guys,

I’m having a lot of trouble with the zwave binding and I’m hoping someone can help me trace the gremlins. I’ve been fighting with the system for a while now.

Environment:
Hardware: odroid XU4 (single board computer) with a zwave network handled by an aeotech zstick.
Software: I’m running OH2.5 M1. The zwave binding version is the latest snapshot
Devices: About 25 zwave devices total.

openhab> list -s | grep wave
305 x Active x  80 x 2.5.0.201908182309    x org.openhab.binding.zwave

For some reason, after the zwave binding does the nightly heal, half of the zwave network will report “Node is not communicating with controller.” This happens even after I do a hardware reset on the controller and re-add all the devices. This status is shown by devices regardless of range. Some devices more than 100ft away are fine, while some within 10ft don’t work.

I can get the devices working again by either flipping a switch in OH or by restarting the binding, but the heal never completes because the devices are marked offline.

Any suggestions are appreciated!

Here is a partial log captured from zwave binding debug during the heal:

2019-08-20 11:58:43.333 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-08-20 11:58:43.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 3278: callback 229
2019-08-20 11:58:43.336 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=229, payload=E5 23 
2019-08-20 11:58:43.337 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 8: TID 3273: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-08-20 11:58:43.338 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: Got NodeNeighborUpdate request.
2019-08-20 11:58:43.339 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 3273: Transaction is current transaction, so clearing!!!!!
2019-08-20 11:58:43.340 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: NodeNeighborUpdate FAILED
2019-08-20 11:58:43.341 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3273: Transaction CANCELLED
2019-08-20 11:58:43.342 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNetworkEvent
2019-08-20 11:58:43.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: notifyTransactionResponse TID:3273 CANCELLED
2019-08-20 11:58:43.343 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3278: Transaction CANCELLED
2019-08-20 11:58:43.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-20 11:58:43.345 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-20 11:58:43.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 3273: Transaction event listener: DONE: CANCELLED -> 
2019-08-20 11:58:43.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: CANCEL while sending message. Requeueing - 2 attempts left!
2019-08-20 11:58:43.348 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@52cf37
2019-08-20 11:58:43.349 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3278: Transaction RESET with 2 retries remaining.
2019-08-20 11:58:43.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2019-08-20 11:58:43.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 3278 to queue - size 4
2019-08-20 11:58:43.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-20 11:58:43.355 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 18 E6 4C 
2019-08-20 11:58:43.358 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 18 E6 4C 
2019-08-20 11:58:43.361 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-20 11:58:43.363 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-20 11:58:43.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-20 11:58:43.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 230
2019-08-20 11:58:43.374 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 E6 23 77 
2019-08-20 11:58:43.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 3278: Transaction not completed
2019-08-20 11:58:43.379 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=230, payload=E6 23 
2019-08-20 11:58:43.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-20 11:58:43.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 230
2019-08-20 11:58:43.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-08-20 11:58:43.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=230, payload=E6 23 
2019-08-20 11:58:43.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 230
2019-08-20 11:58:43.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-08-20 11:58:43.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 230
2019-08-20 11:58:43.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 3278: (Callback 230)
2019-08-20 11:58:43.400 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-08-20 11:58:43.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 3278: callback 230
2019-08-20 11:58:43.404 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=230, payload=E6 23 
2019-08-20 11:58:43.407 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: Got NodeNeighborUpdate request.
2019-08-20 11:58:43.409 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: NodeNeighborUpdate FAILED
2019-08-20 11:58:43.411 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNetworkEvent
2019-08-20 11:58:43.413 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3278: Transaction CANCELLED
2019-08-20 11:58:43.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-20 11:58:43.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: CANCEL while sending message. Requeueing - 1 attempts left!
2019-08-20 11:58:43.420 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3278: Transaction RESET with 1 retries remaining.
2019-08-20 11:58:43.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2019-08-20 11:58:43.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 3278 to queue - size 4
2019-08-20 11:58:43.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-08-20 11:58:43.430 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 18 E7 4D 
2019-08-20 11:58:43.432 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 18 E7 4D 
2019-08-20 11:58:43.435 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-08-20 11:58:43.436 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-08-20 11:58:43.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-20 11:58:43.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 231
2019-08-20 11:58:43.444 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 E7 23 76 
2019-08-20 11:58:43.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 3278: Transaction not completed
2019-08-20 11:58:43.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=231, payload=E7 23 
2019-08-20 11:58:43.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-08-20 11:58:43.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 231
2019-08-20 11:58:43.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-08-20 11:58:43.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=231, payload=E7 23 
2019-08-20 11:58:43.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 231
2019-08-20 11:58:43.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-08-20 11:58:43.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3278: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 231
2019-08-20 11:58:43.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 3278: (Callback 231)
2019-08-20 11:58:43.474 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-08-20 11:58:43.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 3278: callback 231
2019-08-20 11:58:43.478 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=231, payload=E7 23 
2019-08-20 11:58:43.481 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: Got NodeNeighborUpdate request.
2019-08-20 11:58:43.483 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NODE 24: NodeNeighborUpdate FAILED
2019-08-20 11:58:43.485 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNetworkEvent
2019-08-20 11:58:43.488 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3278: Transaction CANCELLED
2019-08-20 11:58:43.490 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-20 11:58:43.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Retry count exceeded. Discarding message: TID 3278: [CANCELLED] priority=Controller, requiresResponse=true, callback: 231
2019-08-20 11:58:43.495 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-20 11:58:43.497 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Setting OFFLINE
2019-08-20 11:58:43.501 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 24: Node Status event - Node is DEAD
2019-08-20 11:58:43.504 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Node is DEAD.
2019-08-20 11:58:43.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-08-20 11:58:43.509 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Setting OFFLINE
2019-08-20 11:58:43.512 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 24: Node Status event - Node is DEAD
2019-08-20 11:58:43.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 3278: Transaction completed
2019-08-20 11:58:43.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:3278 CANCELLED
2019-08-20 11:58:43.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 3278: Transaction event listener: DONE: CANCELLED -> 
2019-08-20 11:58:43.517 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-08-20 11:58:43.520 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@469e48
2019-08-20 11:58:43.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

Bruce_Osborne · August 20, 2019, 10:36pm

A few people, including me, have had some battery powered devices hang during a nightly heal. Right now the advice is to turn off the nightly heal and heal nodes manually as needed.

roy_liao · August 20, 2019, 11:12pm

Got it, thanks! Will try that for now.

roy_liao · August 21, 2019, 8:35am

Sadly, manual heal didn’t work. Healing nodes manually yields the following message. I feel like I must be missing something simple. Node 25 is mains powered, and it was included 24 hours ago, so initialization should be finished right? Excluding/re-including yields the same result

01:34:01.514 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 25: Configuration update received
01:34:01.520 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 25: Configuration update set action_heal to true (Boolean)
01:34:01.524 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 25: Starting heal on node!
01:34:01.527 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 25: Can not start heal as initialisation is not complete (UPDATE_NEIGHBORS).

Bruce_Osborne · August 21, 2019, 9:21am

@chris is our expert.

roy_liao · August 22, 2019, 5:13pm

Here’s the output from Chris’s log viewer. Node 6 in this case is sent the heal command, and almost right away (within 7 seconds), the binding marks it offline. When you change the state in OH, it comes back online immediately. Seeing this with 11 of 25 devices on the zwave network, all mains connected.

Celaeno1 · October 23, 2019, 8:53pm

Is this recommendation still valid? I recently updated to Snapshot 1731. Since then, all my 3 battery powered devices are going crazy. After each heal, it says that they are not communicating with the controller. A manual heal brings them “online” again, but “last heal time and day” is not updated. Previously, these ran 10 months uninterrupted. Had set a daily heal that always worked. Btw, I did not move any device just one millimeter from it’s place.

Bruce_Osborne · October 23, 2019, 9:43pm

My cheap Chinese sensors have been behaving better. I am on 2.5 Milestone 3 with them right now and am setting up a new system on Milestone 4.