ZWave devices cannot communicate with controller

Tags: #<Tag:0x00007fe740997c88> #<Tag:0x00007fe740997ad0> #<Tag:0x00007fe740997990>

I have a few aeotec remotes, wallmote quads and nanomotes. Occassionally, the devices cannot communitate with the aeotec controller. For example, when I tap a button on the wallmotes, they flassh blue 3 times and then red. There is nothing reported in the log when this happens. After a few minutes, or if I disable and then enable the device in PaperUI, everything is fine again, but I’d like to get this fixed. Anyone have any ideas?

First. follow the instructions for when things do not go as planned.

This only shows me how to enable debug logging, which I did. When the devices are not communicating with the controller, nothing appears in the log. Once things have returned to normal, logging resumes.

If nothing shows in the log, the controller is not placed in inclusion mode.

sounds like a range issue, maybe add a couple mains powered devices to extend the mesh?

2 Likes

Two of the devices are no more than 15 ft from the controller. The other two are further away, so I don’t think range is an issue.

“My Break-Dancing days are over, but there’s always the Funky Chicken” – The Full Monty

Here is the log. The controller stopped responding at about the 20:34 mark. Things started working normally after about 2 or 3 minutes.

ZWave Log Viewer.pdf (94.6 KB)

Time for the experts. @5iver or @sihui should be along shortly.

I’m subscribed to everything tagged with zwave, zigbee, jython and jsr223, so no need to ping me :slight_smile:. Chris is the expert and I’m usually just asking the questions that I think he would need answered to figure things out. Sometimes I get lucky in the process!

@lorenzopt, when posting logs, please leave them as text so that they can be looked at in the log viewer. If they are too big, put them in your favorite cloud storage and provide a link. Questions for you…

Which version of OH and binding? How many nodes? When is your daily heal scheduled (you can find it in your controller settings… IIRC it defaults to 2am)?

21:28:58. 287 15 RX RES DeleteSUCReturnRoute STARTED

There are a few of these in the log for different nodes. Was the network healing when this is occurring?

I don’t see any 2-3 minute gap in the log. Is it that devices are not responding to commands… like lights not turning ON/OFF? When this happens, is it just the Aeon devices (which nodes?) or are you also not able to control any zwave devices… like in a UI?

1 Like

Same here btw :smiling_face_with_three_hearts:

1 Like

Please provide the log as a text file - without any filtering. Otherwise it’s really very difficult to use and I can’t process this file.

1 Like

I’m using OH 2.4 with zwave 2.5 snapshot binding from March. There are 23 nodes. When the device is in this odd state, bulbs will not toggle even when the switch is toggled in basic ui. And I noticed that there was no gap in time in the log as well. I can try a more recent snapshot this weekend, but this has been working quite well for some time. My network heal is set for 4am. How can I tell if a a network heal is running?

I find that my Z-Wave network occasionally becomes sluggish and sometimes looses sensor events.
Nothing shows up in the debug logs.
When that happens, I fire up my Z-Wave sniffer and looks for talkative nodes. Just the other day it was my Fibaro RGBW controller spewing out messages to a non existing node address. Power cycling the Fibaro node made it shut up and things were back to normal.
I have also experienced this with Heatit ZTRM2 and Aeotec Multisensor 6.

Does the controller have some “phantom” failed nodes on it that need to be deleted? The non-existing node address came from somewhere…

It was a high node address, 168, my highest is 118. My theory is sw failure on the nodes after weeks of uptime.

You can tell from the log.

So, I power cycled all my mains powered devices, stopped OH and cleaned the cache a couple of times. Now the wave network is almost unresponsive my WallMote flash blue and then red and the target device does not respond. I checked the log for the network heal and I don’t see that a heal has run, What I do see is this:

2019-09-01 08:10:46.099 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 20 hours time.
2019-09-01 08:18:20.171 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update heal_time to 2
2019-09-01 08:18:20.175 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 18 hours time.
2019-09-01 08:18:36.835 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 18 hours time.
2019-09-01 08:19:43.420 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Configuration update set action_heal to true (Boolean)
2019-09-01 08:19:43.423 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Starting heal on node!
2019-09-01 08:19:43.425 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Can not start heal as initialisation is not complete (REQUEST_NIF).
2019-09-01 08:20:41.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Configuration update set action_heal to true (Boolean)
2019-09-01 08:20:41.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Starting heal on node!
2019-09-01 08:20:41.855 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Can not start heal as initialisation is not complete (REQUEST_NIF).
2019-09-01 08:22:19.969 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Configuration update set action_heal to true (Boolean)
2019-09-01 08:22:19.972 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Starting heal on node!
2019-09-01 08:22:19.975 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Can not start heal as initialisation is not complete (REQUEST_NIF).
2019-09-01 08:55:36.826 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Configuration update set action_heal to true (Boolean)
2019-09-01 08:55:36.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Starting heal on node!
2019-09-01 08:55:36.832 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Can not start heal as initialisation is not complete (REQUEST_NIF).
[08:55:43] openhabian@openHABianPi:~$ 

Here is the log log after the last reboot:


2019-09-01 08:24:06.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 336: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:08.073 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 10: TID 336: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:08.075 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 336: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:08.077 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 336: Transaction CANCELLED
2019-09-01 08:24:08.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 08:24:08.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:336 CANCELLED
2019-09-01 08:24:08.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:08.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 336: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:08.089 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 3C A7 
2019-09-01 08:24:08.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@ac162
2019-09-01 08:24:08.092 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 3C A7 
2019-09-01 08:24:08.107 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:08.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 337: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.146 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 08:24:09.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.152 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 00 9A 
2019-09-01 08:24:09.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 329: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 08:24:09.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 08:24:09.160 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 08:24:09.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:09.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 329: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 08:24:09.178 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 08:24:09.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.185 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 08:24:09.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.189 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 08:24:09.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 329: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.197 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.199 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-09-01 08:24:09.201 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 329: Transaction CANCELLED
2019-09-01 08:24:09.203 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: CANCEL while sending message. Requeueing - 1 attempts left!
2019-09-01 08:24:09.205 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 329: Transaction RESET with 1 retries remaining.
2019-09-01 08:24:09.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2019-09-01 08:24:09.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 329 to queue - size 54
2019-09-01 08:24:09.210 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:09.213 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 10 8B 
2019-09-01 08:24:09.215 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 10 8B 
2019-09-01 08:24:09.217 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:09.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.221 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 08:24:09.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 4<>124 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.230 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 00 9A 
2019-09-01 08:24:09.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 5<>123 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 329: Transaction not completed
2019-09-01 08:24:09.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (5): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2019-09-01 08:24:09.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 329: Resetting transaction
2019-09-01 08:24:09.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:329 WAIT_RESPONSE
2019-09-01 08:24:09.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2019-09-01 08:24:09.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 329 to queue - size 54
2019-09-01 08:24:09.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 08:24:09.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (4): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 08:24:09.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 08:24:09.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 08:24:09.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 08:24:09.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 329: Transaction event listener: DONE: WAIT_RESPONSE -> 
2019-09-01 08:24:09.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 08:24:09.282 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@ca1386
2019-09-01 08:24:09.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 08:24:09.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.287 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
2019-09-01 08:24:09.289 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 08:24:09.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-09-01 08:24:09.292 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-09-01 08:24:09.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 08:24:09.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 08:24:09.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:09.503 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 10 8B 
2019-09-01 08:24:09.505 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 10 8B 
2019-09-01 08:24:09.507 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:09.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.759 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 08:24:09.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.764 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 00 9A 
2019-09-01 08:24:09.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 08:24:09.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 08:24:09.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 08:24:09.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 329: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.790 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=00 
2019-09-01 08:24:09.792 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.
2019-09-01 08:24:09.795 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 329: Transaction CANCELLED
2019-09-01 08:24:09.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2019-09-01 08:24:09.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Retry count exceeded. Discarding message: TID 329: [CANCELLED] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:09.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 329: Transaction completed
2019-09-01 08:24:09.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:329 CANCELLED
2019-09-01 08:24:09.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 08:24:09.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1e9fa27
2019-09-01 08:24:09.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 08:24:09.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-09-01 08:24:09.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 338 to queue - size 43
2019-09-01 08:24:09.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:10.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:10.052 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 02 99 
2019-09-01 08:24:10.055 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 02 99 
2019-09-01 08:24:10.057 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:10.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 330: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:10.113 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 60: TID 337: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:10.119 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 337: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:10.125 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 337: Transaction CANCELLED
2019-09-01 08:24:10.128 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 60: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 08:24:10.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: notifyTransactionResponse TID:337 CANCELLED
2019-09-01 08:24:10.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:10.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 337: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:10.136 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 0A 91 
2019-09-01 08:24:10.136 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 60: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1dc8c5d
2019-09-01 08:24:10.139 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 0A 91 
2019-09-01 08:24:10.141 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:10.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 338: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:12.061 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 2: TID 330: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:12.063 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 330: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:12.064 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 330: Transaction CANCELLED
2019-09-01 08:24:12.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:330 CANCELLED
2019-09-01 08:24:12.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:12.091 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 09 92 
2019-09-01 08:24:12.093 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 09 92 
2019-09-01 08:24:12.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 330: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:12.096 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:12.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 334: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:12.098 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1ab30dd
2019-09-01 08:24:12.147 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 10: TID 338: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:12.149 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 338: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:12.151 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 338: Transaction CANCELLED
2019-09-01 08:24:12.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 08:24:12.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:338 CANCELLED
2019-09-01 08:24:12.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:12.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 338: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:12.164 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1d6a604
2019-09-01 08:24:12.165 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 4F 01 00 25 2B A4 
2019-09-01 08:24:12.169 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 79: Sending REQUEST Message = 01 08 00 13 4F 01 00 25 2B A4 
2019-09-01 08:24:12.173 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:12.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 94: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 43
2019-09-01 08:24:14.099 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 9: TID 334: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:14.101 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 334: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:14.103 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 334: Transaction CANCELLED
2019-09-01 08:24:14.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: notifyTransactionResponse TID:334 CANCELLED
2019-09-01 08:24:14.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:14.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 334: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:14.114 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7fc2ca
2019-09-01 08:24:14.115 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 0F 94 
2019-09-01 08:24:14.118 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 0F 94 
2019-09-01 08:24:14.121 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:14.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 335: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:14.178 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 79: TID 94: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:14.180 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-09-01 08:24:14.183 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 94: Transaction ABORTED
2019-09-01 08:24:14.185 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-09-01 08:24:14.189 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-09-01 08:24:14.191 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:14.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:14.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19fbc2
2019-09-01 08:24:14.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 08:24:14.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 339 to queue - size 51
2019-09-01 08:24:14.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:15.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1e9fa27
2019-09-01 08:24:15.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
2019-09-01 08:24:15.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 340 to queue - size 42
2019-09-01 08:24:15.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:16.126 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 15: TID 335: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:16.129 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 335: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:16.131 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 335: Transaction CANCELLED
2019-09-01 08:24:16.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: notifyTransactionResponse TID:335 CANCELLED
2019-09-01 08:24:16.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:16.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 335: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:16.143 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@34dd51
2019-09-01 08:24:16.142 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 02 99 
2019-09-01 08:24:16.150 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 02 99 
2019-09-01 08:24:16.153 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:16.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 339: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 08:24:16.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@d8ce1a
2019-09-01 08:24:16.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: Adding to device queue
2019-09-01 08:24:16.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: Added 341 to queue - size 43
2019-09-01 08:24:16.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:18.158 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 2: TID 339: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:18.161 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 339: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:18.165 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 339: Transaction CANCELLED
2019-09-01 08:24:18.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:339 CANCELLED
2019-09-01 08:24:18.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:18.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 339: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:18.178 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@c6cf11
2019-09-01 08:24:18.192 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 4D 01 00 25 2C A1 
2019-09-01 08:24:18.197 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 77: Sending REQUEST Message = 01 08 00 13 4D 01 00 25 2C A1 
2019-09-01 08:24:18.203 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:18.207 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 255: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 44
2019-09-01 08:24:20.209 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 77: TID 255: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 08:24:20.211 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-09-01 08:24:20.212 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 255: Transaction ABORTED
2019-09-01 08:24:20.215 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-09-01 08:24:20.218 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-09-01 08:24:20.223 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 08:24:20.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:23.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19fbc2
2019-09-01 08:24:23.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 08:24:23.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 342 to queue - size 50
2019-09-01 08:24:23.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 08:24:26.185 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 79: TID 94: Timeout at state ABORTED. 3 retries remaining.
2019-09-01 08:24:26.189 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 94: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:26.193 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 94: Transaction CANCELLED
2019-09-01 08:24:26.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: notifyTransactionResponse TID:94 CANCELLED
2019-09-01 08:24:26.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:26.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 94: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:26.205 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 79: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@821ee4
2019-09-01 08:24:26.210 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 79: Node Init transaction completed with response COMPLETE
2019-09-01 08:24:26.212 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 0A 91 
2019-09-01 08:24:26.213 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 79: Node advancer - advancing to REQUEST_NIF
2019-09-01 08:24:26.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@8ba7d9
2019-09-01 08:24:26.218 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 0A 91 
2019-09-01 08:24:32.214 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 77: TID 255: Timeout at state ABORTED. 3 retries remaining.
2019-09-01 08:24:32.217 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 255: Transaction is current transaction, so clearing!!!!!
2019-09-01 08:24:32.219 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 255: Transaction CANCELLED
2019-09-01 08:24:32.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: notifyTransactionResponse TID:255 CANCELLED
2019-09-01 08:24:32.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 08:24:32.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 255: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 08:24:32.229 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@171313a
2019-09-01 08:24:32.230 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 02 99 
2019-09-01 08:24:32.233 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init transaction completed with response COMPLETE
2019-09-01 08:24:32.234 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 02 99 
2019-09-01 08:24:32.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer - advancing to REQUEST_NIF
2019-09-01 08:24:32.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@984f59
2019-09-01 08:24:39.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@15a916e
2019-09-01 08:24:40.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1d81d7c
2019-09-01 08:25:04.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: sendTransaction ```

Lorenzo
If you just restarted, it will take a little while for the zwave network to ‘settle down’ and become responsive.

Your log looks very similar to what I was seeing when I have this issue…

Have you tried disabling the daily heal and restarting OH?

The first log states that the heal is not running, and can’t be started at this time as the device is not initialised. I’m assuming from the times that these two logs are taken at around the same time, so heal should not be running (since it says heal is at 2AM).

It looks to me like this log came just after a startup. The binding is trying to request the NIF (the first thing pretty much in the initialisation sequence) and it’s failing. The controller is responding with CAN messages which often mean it is overloaded with traffic.

I don’t think this is related to the heal if this is basically the initialisation of the binding as it appears.