ZWave devices cannot communicate with controller

lorenzopt · August 29, 2019, 3:02am

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)

Bruce_Osborne · August 29, 2019, 9:16am

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

5iver · August 29, 2019, 10:08am

I’m subscribed to everything tagged with zwave, zigbee, jython and jsr223, so no need to ping me . 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?

sihui · August 29, 2019, 10:30am

Same here btw

chris · August 29, 2019, 11:09am

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.

lorenzopt · August 29, 2019, 10:12pm

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?

OMR · August 29, 2019, 10:29pm

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.

Bruce_Osborne · August 29, 2019, 10:39pm

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

OMR · August 29, 2019, 10:44pm

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

5iver · August 29, 2019, 11:17pm

You can tell from the log.

lorenzopt · September 1, 2019, 2:02pm

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 ```

Andrew_Rowe · September 1, 2019, 2:26pm

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

5iver · September 1, 2019, 2:30pm

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?

chris · September 1, 2019, 2:54pm

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.

lorenzopt · September 1, 2019, 4:48pm

Sorry, I wasn’t clear there. I meant that I restarted because it was unresponsive.

lorenzopt · September 1, 2019, 4:54pm

So here’s where I am. My zwave network continued to be unresponsive after allowing for “settle” for about an hour after the last reboot. So I stopped OH and installed the latest snapshot along with the xstream jar, restarted. After an hour or so, the network appears stable and devices are responsive. The looks “normal”, but if there is anything in them that might point to a potential problem, I’d like to hear it. If things go bad again, I’ll post another log.

2019-09-01 11:43:10.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:10.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:REQUEST_NIF)
2019-09-01 11:43:10.270 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:10.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY not supported
2019-09-01 11:43:10.276 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_SENSOR_MULTILEVEL V7 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:10.279 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 85: Sensor Type = Luminance(3), Scale = 1
2019-09-01 11:43:10.282 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 85: Sensor Value = 357
2019-09-01 11:43:10.285 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:10.288 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=357
2019-09-01 11:43:10.291 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:f21cd9de:node85:sensor_luminance to 357 % [QuantityType]
2019-09-01 11:43:10.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.
2019-09-01 11:43:10.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18ab86c.
2019-09-01 11:43:10.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:10.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:10.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:10.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:14.240 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 39 06 31 05 01 2A 02 AE 7B 
2019-09-01 11:43:14.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 06 31 05 01 2A 02 AE 
2019-09-01 11:43:14.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 06 31 05 01 2A 02 AE 
2019-09-01 11:43:14.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:14.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:14.260 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:14.262 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:14.266 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:14.268 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:14.271 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Type = Temperature(1), Scale = 1
2019-09-01 11:43:14.274 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Value = 68.6
2019-09-01 11:43:14.277 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:14.279 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=68.6
2019-09-01 11:43:14.283 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:f21cd9de:node57:sensor_temperature to 68.6 °F [QuantityType]
2019-09-01 11:43:14.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:14.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c142a.
2019-09-01 11:43:14.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:14.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:14.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:14.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:14.723 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 39 05 31 05 05 01 45 B9 
2019-09-01 11:43:14.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 05 31 05 05 01 45 
2019-09-01 11:43:14.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 05 31 05 05 01 45 
2019-09-01 11:43:14.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:14.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:14.752 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:14.755 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:14.756 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:14.759 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:14.760 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-01 11:43:14.763 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Value = 69
2019-09-01 11:43:14.765 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:14.767 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=69
2019-09-01 11:43:14.769 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 57: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-01 11:43:14.771 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:f21cd9de:node57:sensor_relhumidity to 69 [DecimalType]
2019-09-01 11:43:14.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:14.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@10acd96.
2019-09-01 11:43:14.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:14.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:14.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:14.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:16.539 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 39 03 80 03 32 79 
2019-09-01 11:43:16.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 03 80 03 32 
2019-09-01 11:43:16.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 03 80 03 32 
2019-09-01 11:43:16.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:16.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:16.559 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:16.562 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2019-09-01 11:43:16.566 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:16.569 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2019-09-01 11:43:16.573 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 57: Battery report value = 50
2019-09-01 11:43:16.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-09-01 11:43:16.580 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=50
2019-09-01 11:43:16.584 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:f21cd9de:node57:battery-level to 50 [DecimalType]
2019-09-01 11:43:16.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:16.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1915bd6.
2019-09-01 11:43:16.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:16.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:16.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:16.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:20.398 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 39 06 31 05 03 0A 00 00 F5 
2019-09-01 11:43:20.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 06 31 05 03 0A 00 00 
2019-09-01 11:43:20.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 06 31 05 03 0A 00 00 
2019-09-01 11:43:20.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:20.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:20.413 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:20.415 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:20.418 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:20.420 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:20.423 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Type = Luminance(3), Scale = 1
2019-09-01 11:43:20.426 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Value = 0E+1
2019-09-01 11:43:20.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:20.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0E+1
2019-09-01 11:43:20.433 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:f21cd9de:node57:sensor_luminance to 0E+1 % [QuantityType]
2019-09-01 11:43:20.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:20.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@112d410.
2019-09-01 11:43:20.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:20.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:20.498 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 39 05 31 05 1B 01 00 E2 
2019-09-01 11:43:20.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 05 31 05 1B 01 00 
2019-09-01 11:43:20.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 05 31 05 1B 01 00 
2019-09-01 11:43:20.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:20.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:20.512 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:20.515 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:20.517 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 39 02 84 07 4B 
2019-09-01 11:43:20.517 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:20.521 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 57: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:20.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 02 84 07 
2019-09-01 11:43:20.525 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Type = Ultraviolet(27), Scale = 0
2019-09-01 11:43:20.528 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 57: Sensor Value = 0E+1
2019-09-01 11:43:20.531 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:20.533 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0E+1
2019-09-01 11:43:20.536 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 57: Sensor conversion not performed for ULTRAVIOLET.
2019-09-01 11:43:20.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:f21cd9de:node57:sensor_ultraviolet to 0 [DecimalType]
2019-09-01 11:43:20.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:20.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1773a5c.
2019-09-01 11:43:20.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=57, callback=0, payload=00 39 02 84 07 
2019-09-01 11:43:20.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:20.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:20.560 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:20.563 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Is awake with 0 messages in the queue
2019-09-01 11:43:20.566 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Start sleep timer at 1000ms
2019-09-01 11:43:20.568 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-09-01 11:43:20.596 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 57: Node Status event - Node is AWAKE
2019-09-01 11:43:20.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Commands processed 1.
2019-09-01 11:43:20.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@483f99.
2019-09-01 11:43:20.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:20.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:20.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:21.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-01 11:43:21.569 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-01 11:43:21.571 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: No more messages, go back to sleep
2019-09-01 11:43:21.572 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 57: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2019-09-01 11:43:21.575 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: SECURITY not supported
2019-09-01 11:43:21.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2019-09-01 11:43:21.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@10c9894
2019-09-01 11:43:21.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Bump transaction 614 priority from Immediate to Immediate
2019-09-01 11:43:21.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Adding to device queue
2019-09-01 11:43:21.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Added 614 to queue - size 35
2019-09-01 11:43:21.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:21.592 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 39 02 84 08 25 0B 7C 
2019-09-01 11:43:21.595 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 57: Sending REQUEST Message = 01 09 00 13 39 02 84 08 25 0B 7C 
2019-09-01 11:43:21.598 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 11:43:21.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 614: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.600 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 11:43:21.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 11:43:21.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 11:43:21.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 614: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.611 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-01 11:43:21.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 11:43:21.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 11:43:21.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:21.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 11:43:21.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 11:43:21.623 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0B 00 00 02 E2 
2019-09-01 11:43:21.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 614: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 11:43:21.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 614: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.631 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 11:43:21.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 02 
2019-09-01 11:43:21.633 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 57: sentData successfully placed on stack.
2019-09-01 11:43:21.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 614: Advanced to WAIT_REQUEST
2019-09-01 11:43:21.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: TID 614: Transaction not completed
2019-09-01 11:43:21.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 02 
2019-09-01 11:43:21.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 614: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 11:43:21.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 614: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 11
2019-09-01 11:43:21.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 614: (Callback 11)
2019-09-01 11:43:21.651 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-01 11:43:21.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 614: callback 11
2019-09-01 11:43:21.655 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=11, payload=0B 00 00 02 
2019-09-01 11:43:21.657 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 57: SendData Request. CallBack ID = 11, Status = Transmission complete and ACK received(0)
2019-09-01 11:43:21.659 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:21.670 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 614: Transaction COMPLETED
2019-09-01 11:43:21.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: Response processed after 73ms
2019-09-01 11:43:21.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: TID 614: Transaction completed
2019-09-01 11:43:21.676 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 57: notifyTransactionResponse TID:614 DONE
2019-09-01 11:43:21.679 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 11:43:21.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 614: Transaction event listener: DONE: DONE -> 
2019-09-01 11:43:21.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:21.682 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 57: Went to sleep COMPLETE
2019-09-01 11:43:21.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:27.347 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 3C 02 84 07 4E 
2019-09-01 11:43:27.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=60, callback=0, payload=00 3C 02 84 07 
2019-09-01 11:43:27.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=60, callback=0, payload=00 3C 02 84 07 
2019-09-01 11:43:27.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:27.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:27.357 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 60: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:27.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: Commands processed 1.
2019-09-01 11:43:27.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 60: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@17e8ead.
2019-09-01 11:43:27.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:27.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:27.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:27.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:50.841 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 02 02 84 07 70 
2019-09-01 11:43:50.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 84 07 
2019-09-01 11:43:50.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 84 07 
2019-09-01 11:43:50.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:50.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:50.851 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:50.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2019-09-01 11:43:50.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6372c6.
2019-09-01 11:43:50.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:50.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:50.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:50.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:54.235 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 41 05 31 05 05 01 3F BB 
2019-09-01 11:43:54.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3F 
2019-09-01 11:43:54.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3F 
2019-09-01 11:43:54.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:43:54.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Application Command Request (ALIVE:DONE)
2019-09-01 11:43:54.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: resetResendCount initComplete=true isDead=false
2019-09-01 11:43:54.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:43:54.246 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: SECURITY not supported
2019-09-01 11:43:54.248 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 65: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:43:54.250 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-01 11:43:54.252 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Value = 63
2019-09-01 11:43:54.254 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:43:54.258 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=63
2019-09-01 11:43:54.261 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 65: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-01 11:43:54.262 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Updating channel state zwave:device:f21cd9de:node65:sensor_relhumidity to 63 [DecimalType]
2019-09-01 11:43:54.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Commands processed 1.
2019-09-01 11:43:54.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@8e028c.
2019-09-01 11:43:54.387 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:54.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:43:54.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:43:54.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:56.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1afcacf
2019-09-01 11:43:56.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 11:43:56.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 417 to queue - size 29
2019-09-01 11:43:56.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:56.390 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 02 99 
2019-09-01 11:43:56.394 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 60 02 99 
2019-09-01 11:43:56.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 417: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 11:43:58.400 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 2: TID 417: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 11:43:58.404 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 417: Transaction is current transaction, so clearing!!!!!
2019-09-01 11:43:58.407 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 417: Transaction CANCELLED
2019-09-01 11:43:58.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:417 CANCELLED
2019-09-01 11:43:58.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:43:58.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 417: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 11:43:58.416 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@5e25b6
2019-09-01 11:44:04.274 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 41 05 31 05 05 01 3E BA 
2019-09-01 11:44:04.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3E 
2019-09-01 11:44:04.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3E 
2019-09-01 11:44:04.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:44:04.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Application Command Request (ALIVE:DONE)
2019-09-01 11:44:04.288 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: resetResendCount initComplete=true isDead=false
2019-09-01 11:44:04.291 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:44:04.292 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: SECURITY not supported
2019-09-01 11:44:04.293 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 65: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:44:04.295 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-01 11:44:04.299 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Value = 62
2019-09-01 11:44:04.303 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:44:04.307 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=62
2019-09-01 11:44:04.311 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 65: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-01 11:44:04.312 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Updating channel state zwave:device:f21cd9de:node65:sensor_relhumidity to 62 [DecimalType]
2019-09-01 11:44:04.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Commands processed 1.
2019-09-01 11:44:04.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d34733.
2019-09-01 11:44:04.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:04.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:04.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:44:04.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:44:43.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@5776c0
2019-09-01 11:44:43.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2019-09-01 11:44:43.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 418 to queue - size 29
2019-09-01 11:44:43.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:44:43.435 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 18 83 
2019-09-01 11:44:43.438 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 60 18 83 
2019-09-01 11:44:43.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 418: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 11:44:44.336 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 41 05 31 05 05 01 3F BB 
2019-09-01 11:44:44.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3F 
2019-09-01 11:44:44.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3F 
2019-09-01 11:44:44.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:44:44.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Application Command Request (ALIVE:DONE)
2019-09-01 11:44:44.353 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: resetResendCount initComplete=true isDead=false
2019-09-01 11:44:44.356 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:44:44.359 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: SECURITY not supported
2019-09-01 11:44:44.361 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 65: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:44:44.364 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-01 11:44:44.367 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Value = 63
2019-09-01 11:44:44.370 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:44:44.373 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=63
2019-09-01 11:44:44.377 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 65: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-01 11:44:44.380 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Updating channel state zwave:device:f21cd9de:node65:sensor_relhumidity to 63 [DecimalType]
2019-09-01 11:44:44.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Commands processed 1.
2019-09-01 11:44:44.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@fdb182.
2019-09-01 11:44:44.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:44.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:44.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:44:44.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:44:45.442 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 24: TID 418: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 11:44:45.445 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 418: Transaction is current transaction, so clearing!!!!!
2019-09-01 11:44:45.447 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 418: Transaction CANCELLED
2019-09-01 11:44:45.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:418 CANCELLED
2019-09-01 11:44:45.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:44:45.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 418: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 11:44:45.466 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@b4a940
2019-09-01 11:44:54.357 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 41 05 31 05 05 01 3E BA 
2019-09-01 11:44:54.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3E 
2019-09-01 11:44:54.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=65, callback=0, payload=00 41 05 31 05 05 01 3E 
2019-09-01 11:44:54.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 11:44:54.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Application Command Request (ALIVE:DONE)
2019-09-01 11:44:54.368 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: resetResendCount initComplete=true isDead=false
2019-09-01 11:44:54.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-01 11:44:54.371 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 65: SECURITY not supported
2019-09-01 11:44:54.372 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 65: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-01 11:44:54.374 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-01 11:44:54.375 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 65: Sensor Value = 62
2019-09-01 11:44:54.377 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-01 11:44:54.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=62
2019-09-01 11:44:54.381 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 65: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-01 11:44:54.383 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Updating channel state zwave:device:f21cd9de:node65:sensor_relhumidity to 62 [DecimalType]
2019-09-01 11:44:54.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Commands processed 1.
2019-09-01 11:44:54.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@16d1959.
2019-09-01 11:44:54.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:54.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 11:44:54.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 11:44:54.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:46:27.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@d2c5a8
2019-09-01 11:46:27.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: Adding to device queue
2019-09-01 11:46:27.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: Added 419 to queue - size 29
2019-09-01 11:46:27.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:46:27.544 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 3B A0 
2019-09-01 11:46:27.547 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 60 3B A0 
2019-09-01 11:46:27.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 419: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 11:46:29.550 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 59: TID 419: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 11:46:29.552 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 419: Transaction is current transaction, so clearing!!!!!
2019-09-01 11:46:29.555 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 419: Transaction CANCELLED
2019-09-01 11:46:29.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: notifyTransactionResponse TID:419 CANCELLED
2019-09-01 11:46:29.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 11:46:29.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 419: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 11:46:29.603 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1ad8882

Bruce_Osborne · September 1, 2019, 4:57pm

You could also upload to the log viewer to see id anything looks suspicious.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

chris · September 1, 2019, 5:40pm

This log looks pretty normal, but it’s short. The previous log shows a lot of CAN messages as I said earlier. These are often indicative of the controller being overloaded. In the past I’ve seen that these have been caused when a device floods the network.

lorenzopt · September 1, 2019, 7:02pm

OK, thanks. I may have to get a sniffer to find out just which devices may be flooding the network.
But since my last report, I ran into the issue again. I tapped a button on my wall mote, it flashed blue a few times, then red. There was no console output when the button was pressed ( I’m running tail -f on the log file). The bulb did not toggle.

Here is the log just before it happened:

2019-09-01 13:55:34.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 13:55:34.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:55:34.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 242 to queue - size 39
2019-09-01 13:55:34.100 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:55:34.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 13:55:34.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 241: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 13:55:34.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 13:55:34.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:55:34.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 241: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 13:55:34.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 13:55:34.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 241: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 13:55:34.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:55:34.130 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2019-09-01 13:55:34.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 241: Advanced to WAIT_DATA
2019-09-01 13:55:34.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 241: Transaction not completed
2019-09-01 13:55:34.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:55:34.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:55:41.832 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: ZWaveCommandClassTransactionPayload - send to node
2019-09-01 13:55:41.835 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 59: SECURITY not supported
2019-09-01 13:55:41.837 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 59: Command Class COMMAND_CLASS_METER is NOT required to be secured
2019-09-01 13:55:41.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@f478e
2019-09-01 13:55:41.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: Adding to device queue
2019-09-01 13:55:41.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: Added 243 to queue - size 40
2019-09-01 13:55:41.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:55:59.134 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 15: TID 241: Timeout at state WAIT_DATA. 3 retries remaining.
2019-09-01 13:55:59.138 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 241: Transaction is current transaction, so clearing!!!!!
2019-09-01 13:55:59.141 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 241: Transaction CANCELLED
2019-09-01 13:55:59.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: notifyTransactionResponse TID:241 CANCELLED
2019-09-01 13:55:59.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:55:59.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 241: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 13:55:59.153 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 13 02 26 02 25 57 A2 
2019-09-01 13:55:59.153 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init response (4) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@76bec6
2019-09-01 13:55:59.157 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 09 00 13 13 02 26 02 25 57 A2 
2019-09-01 13:55:59.158 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: No data from device, but it was ACK'd. Possibly not supported? (Try 4)
2019-09-01 13:55:59.161 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:55:59.163 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init transaction retries exceeded
2019-09-01 13:55:59.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 240: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 87
2019-09-01 13:55:59.167 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer: Restored from file - skipping static initialisation
2019-09-01 13:55:59.171 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer - advancing to STATIC_END
2019-09-01 13:55:59.174 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 15: Serialise aborted as static stages not complete
2019-09-01 13:55:59.177 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer - advancing to DYNAMIC_VALUES
2019-09-01 13:55:59.180 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MANUFACTURER_SPECIFIC
2019-09-01 13:55:59.183 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_POWERLEVEL
2019-09-01 13:55:59.185 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Found 1 instances of COMMAND_CLASS_POWERLEVEL for endpoint 0
2019-09-01 13:55:59.190 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 15: Creating new message for application command POWERLEVEL_GET
2019-09-01 13:55:59.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported
2019-09-01 13:55:59.196 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured
2019-09-01 13:55:59.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: ZWaveCommandClassTransactionPayload - send to node
2019-09-01 13:55:59.202 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported
2019-09-01 13:55:59.204 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured
2019-09-01 13:55:59.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@bfa94
2019-09-01 13:55:59.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue
2019-09-01 13:55:59.215 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Added 244 to queue - size 40
2019-09-01 13:55:59.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:56:01.168 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 19: TID 240: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 13:56:01.170 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-09-01 13:56:01.172 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 240: Transaction ABORTED
2019-09-01 13:56:01.176 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-09-01 13:56:01.179 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-09-01 13:56:01.182 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:01.185 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:56:13.175 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 19: TID 240: Timeout at state ABORTED. 3 retries remaining.
2019-09-01 13:56:13.177 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 240: Transaction is current transaction, so clearing!!!!!
2019-09-01 13:56:13.179 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 240: Transaction CANCELLED
2019-09-01 13:56:13.180 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 13:56:13.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:240 CANCELLED
2019-09-01 13:56:13.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:56:13.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 240: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 13:56:13.187 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 02 04 31 04 03 00 25 58 AA 
2019-09-01 13:56:13.188 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1b8c976
2019-09-01 13:56:13.192 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node Init transaction completed with response COMPLETE
2019-09-01 13:56:13.192 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0B 00 13 02 04 31 04 03 00 25 58 AA 
2019-09-01 13:56:13.195 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:13.194 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_DEVICE_RESET_LOCALLY
2019-09-01 13:56:13.198 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 242: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 88
2019-09-01 13:56:13.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_VERSION
2019-09-01 13:56:13.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: Initialisation complete!
2019-09-01 13:56:13.202 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer - advancing to DYNAMIC_END
2019-09-01 13:56:13.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-09-01 13:56:13.207 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 19: Serializing to file /var/lib/openhab2/zwave/network_ef958966__node_19.xml
2019-09-01 13:56:13.241 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer - advancing to DONE
2019-09-01 13:56:13.243 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-09-01 13:56:13.246 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 19: Serializing to file /var/lib/openhab2/zwave/network_ef958966__node_19.xml
2019-09-01 13:56:15.201 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 2: TID 242: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 13:56:15.204 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-09-01 13:56:15.207 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 242: Transaction ABORTED
2019-09-01 13:56:15.212 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-09-01 13:56:15.215 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-09-01 13:56:15.220 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:15.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:56:19.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1a182bb
2019-09-01 13:56:19.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Adding to device queue
2019-09-01 13:56:19.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: Added 245 to queue - size 40
2019-09-01 13:56:19.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.












2019-09-01 13:56:27.212 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 2: TID 242: Timeout at state ABORTED. 3 retries remaining.
2019-09-01 13:56:27.215 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 242: Transaction is current transaction, so clearing!!!!!
2019-09-01 13:56:27.218 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 242: Transaction CANCELLED
2019-09-01 13:56:27.222 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 13:56:27.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:242 CANCELLED
2019-09-01 13:56:27.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:56:27.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 242: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 13:56:27.234 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1940567
2019-09-01 13:56:27.235 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 4F D4 
2019-09-01 13:56:27.238 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response COMPLETE
2019-09-01 13:56:27.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2019-09-01 13:56:27.240 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 4F D4 
2019-09-01 13:56:27.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
2019-09-01 13:56:27.245 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:27.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 245: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-01 13:56:27.255 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: ZWaveCommandClassTransactionPayload - send to node
2019-09-01 13:56:27.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2019-09-01 13:56:27.271 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured
2019-09-01 13:56:27.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@d5d956
2019-09-01 13:56:27.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 13:56:27.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 246 to queue - size 40
2019-09-01 13:56:27.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:56:29.254 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 79: TID 245: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 13:56:29.255 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 245: Transaction is current transaction, so clearing!!!!!
2019-09-01 13:56:29.258 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 245: Transaction CANCELLED
2019-09-01 13:56:29.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 79: notifyTransactionResponse TID:245 CANCELLED
2019-09-01 13:56:29.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:56:29.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 245: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 13:56:29.266 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 79: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@101b7d9
2019-09-01 13:56:29.267 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 3B 03 32 01 18 25 59 89 
2019-09-01 13:56:29.270 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 59: Sending REQUEST Message = 01 0A 00 13 3B 03 32 01 18 25 59 89 
2019-09-01 13:56:29.272 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:29.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 243: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 89
2019-09-01 13:56:31.288 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 59: TID 243: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-01 13:56:31.293 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2019-09-01 13:56:31.297 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 243: Transaction ABORTED
2019-09-01 13:56:31.301 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2019-09-01 13:56:31.306 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2019-09-01 13:56:31.309 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:56:31.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.














2019-09-01 13:56:43.300 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 59: TID 243: Timeout at state ABORTED. 3 retries remaining.
2019-09-01 13:56:43.302 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 243: Transaction is current transaction, so clearing!!!!!
2019-09-01 13:56:43.304 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 243: Transaction CANCELLED
2019-09-01 13:56:43.305 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 59: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-01 13:56:43.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 59: notifyTransactionResponse TID:243 CANCELLED
2019-09-01 13:56:43.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:56:43.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 243: Transaction event listener: DONE: CANCELLED -> 
2019-09-01 13:56:43.312 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 02 04 31 04 04 00 25 5A AF 
2019-09-01 13:56:43.314 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0B 00 13 02 04 31 04 04 00 25 5A AF 
2019-09-01 13:56:43.317 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node Init response (3) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@670457
2019-09-01 13:56:43.319 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node Init transaction completed with response COMPLETE
2019-09-01 13:56:43.320 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node advancer: Initialisation complete!
2019-09-01 13:56:43.322 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node advancer - advancing to DYNAMIC_END
2019-09-01 13:56:43.324 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 59: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-09-01 13:56:43.325 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 59: Serializing to file /var/lib/openhab2/zwave/network_ef958966__node_59.xml
2019-09-01 13:56:43.370 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 59: Node advancer - advancing to DONE
2019-09-01 13:56:43.372 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 59: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2019-09-01 13:56:43.375 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 59: Serializing to file /var/lib/openhab2/zwave/network_ef958966__node_59.xml
2019-09-01 13:57:00.016 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:57:00.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 13:57:00.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 13:57:00.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 13:57:00.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 13:57:00.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:57:00.031 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-01 13:57:00.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.036 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 13:57:00.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.042 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.042 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.044 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2019-09-01 13:57:00.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 246: Advanced to WAIT_REQUEST
2019-09-01 13:57:00.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 246: Transaction not completed
2019-09-01 13:57:00.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.048 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2019-09-01 13:57:00.053 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 246: Resetting transaction
2019-09-01 13:57:00.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:246 WAIT_REQUEST
2019-09-01 13:57:00.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2019-09-01 13:57:00.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 246 to queue - size 39
2019-09-01 13:57:00.060 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 13:57:00.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 246: Transaction event listener: DONE: WAIT_REQUEST -> 
2019-09-01 13:57:00.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 3<>125 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.066 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.066 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Completing UNINTIALIZED transaction 246!!! How?!?
2019-09-01 13:57:00.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.072 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1331a98
2019-09-01 13:57:00.076 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.075 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2019-09-01 13:57:00.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 2<>126 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.084 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 3F 09 60 0D 00 01 5B 03 7D 00 01 8A 
2019-09-01 13:57:00.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2019-09-01 13:57:00.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 09 60 0D 00 01 5B 03 7D 00 01 
2019-09-01 13:57:00.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.097 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 09 60 0D 00 01 5B 03 7D 00 01 
2019-09-01 13:57:00.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.101 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:REQUEST_NIF)
2019-09-01 13:57:00.103 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-09-01 13:57:00.105 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0
2019-09-01 13:57:00.108 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2019-09-01 13:57:00.109 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_CENTRAL_SCENE V2 CENTRAL_SCENE_NOTIFICATION
2019-09-01 13:57:00.112 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 63: Received scene 1 at key 0 [Single Press]
2019-09-01 13:57:00.115 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-09-01 13:57:00.117 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_CENTRAL_SCENE, value=1.0
2019-09-01 13:57:00.120 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Updating channel state zwave:device:f21cd9de:node63:scene_number to 1.0 [DecimalType]
2019-09-01 13:57:00.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2019-09-01 13:57:00.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@354501.
2019-09-01 13:57:00.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 13:57:00.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-01 13:57:00.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 13:57:00.246 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 57 00 00 16 AA 
2019-09-01 13:57:00.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=87, payload=57 00 00 16 
2019-09-01 13:57:00.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=87, payload=57 00 00 16 
2019-09-01 13:57:00.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-01 13:57:00.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-09-01 13:57:00.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-09-01 13:57:00.258 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=87, payload=57 00 00 16 
2019-09-01 13:57:00.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2019-09-01 13:57:00.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-01 13:57:00.309 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 02 04 31 04 04 00 25 5A AF 
2019-09-01 13:57:00.312 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0B 00 13 02 04 31 04 04 00 25 5A AF 
2019-09-01 13:57:00.315 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-01 13:57:00.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.317 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-01 13:57:00.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 13:57:00.321 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-01 13:57:00.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.324 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-01 13:57:00.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-01 13:57:00.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:57:00.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 13:57:00.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 246: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.345 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-01 13:57:00.349 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2019-09-01 13:57:00.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 246: Advanced to WAIT_REQUEST
2019-09-01 13:57:00.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 246: Transaction not completed
2019-09-01 13:57:00.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:57:00.377 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5A 00 00 06 B7 
2019-09-01 13:57:00.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=90, payload=5A 00 00 06 
2019-09-01 13:57:00.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=90, payload=5A 00 00 06 
2019-09-01 13:57:00.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 246: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-01 13:57:00.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 246: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 90
2019-09-01 13:57:00.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 246: (Callback 90)
2019-09-01 13:57:00.401 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-01 13:57:00.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 246: callback 90
2019-09-01 13:57:00.408 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=90, payload=5A 00 00 06 
2019-09-01 13:57:00.411 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 90, Status = Transmission complete and ACK received(0)
2019-09-01 13:57:00.415 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 246: Advanced to WAIT_DATA
2019-09-01 13:57:00.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 246: Transaction not completed
2019-09-01 13:57:00.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-01 13:57:00.423 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 13 03 26 03 00 C7 
2019-09-01 13:57:00.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-01 13:57:00.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=19, callback=0, payload=00 13 03 26 03 00 
2019-09-01 13:57:00.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=19, callback=0, payload=00 13 03 26 03 00 
2019-09-01 13:57:00.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

sihui · September 1, 2019, 9:24pm

Same as before, lot’s of CAN and a 61 seconds delay for node 19: