18:41:41.747 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false. 18:42:36.273 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null 18:42:41.553 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller 18:42:41.556 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false. 18:43:18.313 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener. 18:43:18.346 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serializing to file /openhab/userdata/zwave/network_defd38d5__node_3.xml 18:43:18.424 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Disposing receive thread 18:43:18.485 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive 18:43:18.490 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Receive thread dispose 18:43:18.491 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Disposing serial connection 18:43:18.502 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Serial connection disposed 18:43:18.504 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler 18:43:18.506 [DEBUG] [ave.internal.protocol.ZWaveController] - Shutting down ZWave controller 18:43:18.507 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Shutting down transaction manager 18:43:18.509 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Exiting ZWave Receive Thread 18:43:23.442 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Deactivate zwave:serial_zstick:a94d59a1 18:43:23.516 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWave Transaction manager failed to terminate properly, forcing shutdown 18:43:23.519 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction manager shutdown 18:43:23.522 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction exception java.util.concurrent.ExecutionException: java.lang.InterruptedException at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_232] at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_232] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:442) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.access$6(ZWaveNodeInitStageAdvancer.java:373) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?] Caused by: java.lang.InterruptedException at java.lang.Object.wait(Native Method) ~[?:1.8.0_232] at java.lang.Object.wait(Object.java:502) ~[?:1.8.0_232] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_232] at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_232] 18:43:23.574 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response null 18:43:23.575 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Skipping initialization thread, process stopped by controller 18:43:23.577 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller shutdown 18:43:34.952 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:a94d59a1 with scan time of 60 18:43:34.957 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:a94d59a1 18:43:34.960 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null 18:43:35.120 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 18:43:35.126 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:a94d59a1. 18:43:35.257 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:a94d59a1:node3. 18:43:35.264 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:a94d59a1:node3:switch_dimmer linked - polling started. 18:43:35.265 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:a94d59a1:node3:sensor_binary3 linked - polling started. 18:43:40.151 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0' 18:43:40.172 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Starting receive thread 18:43:40.185 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive 18:43:40.188 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized 18:43:40.194 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller 18:43:40.255 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:40.255 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller 18:43:40.260 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:40.263 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false. 18:43:40.271 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added. 18:43:40.279 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added. 18:43:40.284 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 8 hours time. 18:43:43.270 [DEBUG] [l.ZWaveController$InitializeDelayTask] - Initialising network 18:43:43.311 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1 18:43:43.315 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.328 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 18:43:43.333 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 18:43:43.343 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.342 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.348 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.351 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.354 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.356 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 30 35 00 01 97 18:43:43.363 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.364 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1 18:43:43.370 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 34 2E 30 35 00 01 18:43:43.370 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.381 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 34 2E 30 35 00 01 18:43:43.387 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.388 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2 18:43:43.395 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.399 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.403 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.408 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 34 2E 30 35 00 01 18:43:43.408 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3 18:43:43.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.419 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID 18:43:43.423 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4 18:43:43.426 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.441 [DEBUG] [.serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 4.05, Library Type=1 18:43:43.444 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED 18:43:43.449 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 98ms 18:43:43.452 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed 18:43:43.456 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE 18:43:43.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.473 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 18:43:43.477 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 18:43:43.480 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.482 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.487 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.492 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.493 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 DE FD 38 D5 01 19 18:43:43.496 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.501 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=DE FD 38 D5 01 18:43:43.501 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.506 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=DE FD 38 D5 01 18:43:43.510 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.513 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.517 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.520 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=DE FD 38 D5 01 18:43:43.524 [DEBUG] [serialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xdefd38d5, Controller Node id = 1 18:43:43.528 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED 18:43:43.531 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 47ms 18:43:43.534 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed 18:43:43.537 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE 18:43:43.541 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.550 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 18:43:43.554 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 18:43:43.558 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.559 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.571 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.574 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.575 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 0E 18:43:43.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.584 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.585 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 18:43:43.587 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 18:43:43.597 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.600 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.603 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.608 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 05 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 18:43:43.612 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - API Version = 5.5 18:43:43.616 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x115 18:43:43.619 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Device Type = 0x400 18:43:43.622 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Device ID = 0x1 18:43:43.626 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED 18:43:43.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3 18:43:43.634 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.637 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 74ms 18:43:43.640 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed 18:43:43.644 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE 18:43:43.650 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.653 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.656 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 18:43:43.660 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 18:43:43.663 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.666 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.667 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.670 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.675 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.675 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 18:43:43.678 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.682 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 18:43:43.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.688 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 18:43:43.692 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.696 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.703 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 18:43:43.707 [DEBUG] [sage.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15 18:43:43.710 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED 18:43:43.714 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 46ms 18:43:43.717 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed 18:43:43.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE 18:43:43.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.729 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.733 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 18:43:43.736 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 18:43:43.740 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.741 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.744 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.747 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.752 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.753 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 01 AD 18:43:43.756 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.760 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 18:43:43.761 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.767 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 18:43:43.770 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.774 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.777 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.781 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 18:43:43.785 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response. 18:43:43.789 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - NODE 1: Node is SUC. 18:43:43.793 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED 18:43:43.798 [DEBUG] [GetControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message 18:43:43.802 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2 18:43:43.806 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.809 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 66ms 18:43:43.812 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed 18:43:43.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE 18:43:43.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:43.830 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 18:43:43.834 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 18:43:43.837 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:43.839 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:43.841 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.844 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.848 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:43.852 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:43.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:43.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:43.932 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 05 08 1D 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 CB 18:43:43.939 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=05 08 1D 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 18:43:43.944 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=05 08 1D 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 18:43:43.947 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.950 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:43.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:43.958 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=05 08 1D 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00 18:43:43.961 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response. 18:43:43.965 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - NODE 1: Node found 18:43:43.968 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - NODE 2: Node found 18:43:43.971 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - NODE 3: Node found 18:43:43.975 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API 18:43:43.978 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller 18:43:43.981 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------ 18:43:43.984 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - # Nodes = 3 18:43:43.987 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ---------------------------------------------------------------------------- 18:43:43.990 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 5: Transaction COMPLETED 18:43:44.000 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Init node thread start 18:43:44.001 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 3: Init node thread start 18:43:44.000 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 2: Init node thread start 18:43:44.003 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 162ms 18:43:44.003 [DEBUG] [ave.internal.protocol.ZWaveController] - Starting waiting for init threads 18:43:44.011 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 5: Transaction completed 18:43:44.018 [DEBUG] [ave.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init 18:43:44.021 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:5 DONE 18:43:44.029 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.039 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:44.043 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 18:43:44.046 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 18:43:44.050 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:44.052 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:44.054 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.057 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.062 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.066 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.063 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 1C E3 18:43:44.070 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:44.075 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 18:43:44.077 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.084 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:44.088 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 18:43:44.092 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.095 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:44.102 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.105 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 18:43:44.111 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is secondary = false 18:43:44.116 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is on other network = false 18:43:44.120 [DEBUG] [GetControllerCapabilitiesMessageClass] - Node ID Server is present = false 18:43:44.124 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is real primary = true 18:43:44.128 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is SUC = true 18:43:44.131 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 6: Transaction COMPLETED 18:43:44.135 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 81ms 18:43:44.138 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 6: Transaction completed 18:43:44.142 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6 DONE 18:43:44.148 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.151 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:44.326 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /openhab/userdata/zwave/network_defd38d5__node_1.xml 18:43:44.327 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serializing from file /openhab/userdata/zwave/network_defd38d5__node_3.xml 18:43:44.327 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 2: Serializing from file /openhab/userdata/zwave/network_defd38d5__node_2.xml 18:43:44.355 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 2: Error serializing from file: file does not exist. 18:43:44.363 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Restore from config: Ok. 18:43:44.385 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from EMPTYNODE 18:43:44.392 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 2: Init node thread finished 18:43:44.403 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to IDENTIFY_NODE 18:43:44.405 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created 18:43:44.407 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Initialisation starting 18:43:44.409 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 18:43:44.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@14b8ee 18:43:44.415 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE 18:43:44.421 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Init node thread finished 18:43:44.423 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE 18:43:44.423 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 7 to queue - size 1 18:43:44.426 [DEBUG] [ave.internal.protocol.ZWaveController] - Init thread Node_1_init complete 18:43:44.430 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting 18:43:44.432 [DEBUG] [ave.internal.protocol.ZWaveController] - Waiting for init thread Node_2_init 18:43:44.436 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@e00b2f 18:43:44.440 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:44.438 [DEBUG] [ave.internal.protocol.ZWaveController] - Init thread Node_2_init complete 18:43:44.447 [DEBUG] [ave.internal.protocol.ZWaveController] - Waiting for init thread Node_3_init 18:43:44.451 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8 18:43:44.462 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8 18:43:44.467 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:44.469 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:44.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.473 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.476 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 8 to queue - size 1 18:43:44.481 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 00 04 08 04 71 18:43:44.478 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.483 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 3: Restore from config: Ok. 18:43:44.488 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 00 04 08 04 18:43:44.490 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.491 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_METER, endpoint 0 created 18:43:44.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:44.499 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created 18:43:44.496 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:44.505 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 18:43:44.508 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 00 04 08 04 18:43:44.510 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 18:43:44.513 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.516 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL, endpoint 0 created 18:43:44.518 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:44.520 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 18:43:44.524 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.528 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 18:43:44.531 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 00 04 08 04 18:43:44.534 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_ALL, endpoint 0 created 18:43:44.536 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: ProtocolInfo 18:43:44.539 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 18:43:44.541 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Listening = false 18:43:44.543 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_VERSION, endpoint 0 created 18:43:44.546 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Routing = true 18:43:44.548 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 18:43:44.550 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Beaming = true 18:43:44.553 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0 created 18:43:44.555 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Version = 4 18:43:44.557 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 18:43:44.559 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: FLIRS = false 18:43:44.562 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created 18:43:44.564 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false 18:43:44.566 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_BASIC, endpoint 0 created 18:43:44.568 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Max Baud = 40000 18:43:44.571 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 18:43:44.573 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Basic = BASIC_TYPE_ROUTING_SLAVE 18:43:44.576 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ALARM, endpoint 0 created 18:43:44.579 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Generic = GENERIC_TYPE_THERMOSTAT 18:43:44.580 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed 18:43:44.584 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 2: Specific = SPECIFIC_TYPE_SETPOINT_THERMOSTAT 18:43:44.589 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 18:43:44.595 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 18:43:44.599 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Version = 1, version set. Enabling extra functionality. 18:43:44.604 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 18:43:44.608 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class COMMAND_CLASS_BASIC 18:43:44.614 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_BASIC, endpoint 0 created 18:43:44.618 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 18:43:44.622 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 7: Transaction COMPLETED 18:43:44.626 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 156ms 18:43:44.630 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 7: Transaction completed 18:43:44.633 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:7 DONE 18:43:44.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 7: Transaction event listener: DONE: DONE -> 18:43:44.642 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:44.657 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7e4e7c 18:43:44.658 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 18:43:44.661 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response COMPLETE 18:43:44.664 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 18:43:44.666 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to REQUEST_NIF 18:43:44.670 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:44.669 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:44.675 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.677 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:44.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@f7b879 18:43:44.683 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 93 16 01 02 02 01 33 18:43:44.688 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.693 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Bump transaction 9 priority from Controller to Immediate 18:43:44.697 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:44.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue 18:43:44.697 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=93 16 01 02 02 01 18:43:44.703 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Added 9 to queue - size 1 18:43:44.701 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:44.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:44.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=93 16 01 02 02 01 18:43:44.734 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.737 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:44.741 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:44.744 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=93 16 01 02 02 01 18:43:44.748 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo 18:43:44.752 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true 18:43:44.755 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Routing = false 18:43:44.759 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming = true 18:43:44.762 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Version = 4 18:43:44.766 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS = false 18:43:44.769 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Security = false 18:43:44.772 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud = 40000 18:43:44.776 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Basic = BASIC_TYPE_STATIC_CONTROLLER 18:43:44.780 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Generic = GENERIC_TYPE_STATIC_CONTROLLER 18:43:44.784 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_PC_CONTROLLER 18:43:44.787 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 18:43:44.791 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 18:43:44.795 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality. 18:43:44.798 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 18:43:44.802 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC 18:43:44.806 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created 18:43:44.810 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 18:43:44.813 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 8: Transaction COMPLETED 18:43:44.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 141ms 18:43:44.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 8: Transaction completed 18:43:44.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:8 DONE 18:43:44.829 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:44.829 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 8: Transaction event listener: DONE: DONE -> 18:43:44.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:44.836 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@18605f 18:43:44.844 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE 18:43:44.850 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation 18:43:44.854 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE 18:43:44.859 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /openhab/userdata/zwave/network_defd38d5__node_1.xml 18:43:52.871 [DEBUG] [ng.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:serial_zstick has no references! 18:43:52.891 [DEBUG] [ng.zwave.internal.ZWaveConfigProvider] - ZWave product zwave:device has no references! 18:43:52.916 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery resolved to thingType zwave:qubino_zmnhdd_00_000 18:43:52.924 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from EMPTYNODE 18:43:52.929 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 3: Init node thread finished 18:43:52.929 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to IDENTIFY_NODE 18:43:52.932 [DEBUG] [ave.internal.protocol.ZWaveController] - Init thread Node_3_init complete 18:43:52.938 [DEBUG] [ave.internal.protocol.ZWaveController] - All init threads complete 18:43:52.938 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Initialisation starting 18:43:52.941 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true 18:43:52.944 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1744a7b 18:43:52.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 10 to queue - size 1 18:43:52.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:52.955 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE. 18:43:52.960 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 03 B9 18:43:52.961 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation. 18:43:52.967 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 03 B9 18:43:52.973 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. 18:43:52.982 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=345 18:43:52.987 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:52.988 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=345. SET. Was 345 18:43:52.984 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:52.991 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:52.994 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised 18:43:52.998 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:52.995 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 10: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.003 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:53.007 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:53.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.011 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.014 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 11 01 EC 18:43:53.018 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[node_3]]: Adding node_3 18:43:53.020 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:53.022 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[node_3]]: Adding node_3 18:43:53.024 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 11 01 18:43:53.028 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=6, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.030 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 11 01 18:43:53.032 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=7, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.034 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 10: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.037 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=9, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.039 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.042 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=10, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.044 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 10: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.048 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added. 18:43:53.049 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 11 01 18:43:53.052 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node... 18:43:53.053 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: ProtocolInfo 18:43:53.057 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Listening = true 18:43:53.061 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Routing = true 18:43:53.064 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Beaming = true 18:43:53.067 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Version = 4 18:43:53.070 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: FLIRS = false 18:43:53.073 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Security = false 18:43:53.076 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Max Baud = 40000 18:43:53.080 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Basic = BASIC_TYPE_ROUTING_SLAVE 18:43:53.083 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Generic = GENERIC_TYPE_SWITCH_MULTILEVEL 18:43:53.086 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 3: Specific = SPECIFIC_TYPE_POWER_SWITCH_MULTILEVEL 18:43:53.089 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 18:43:53.093 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 18:43:53.097 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Version = 1, version set. Enabling extra functionality. 18:43:53.100 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 18:43:53.103 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_BASIC 18:43:53.107 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_BASIC, endpoint 0 created 18:43:53.110 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 18:43:53.114 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 10: Transaction COMPLETED 18:43:53.114 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_binary for OnOffType 18:43:53.117 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 122ms 18:43:53.120 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_binary for OnOffType 18:43:53.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 10: Transaction completed 18:43:53.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:10 DONE 18:43:53.126 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer for OnOffType 18:43:53.129 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 10: Transaction event listener: DONE: DONE -> 18:43:53.130 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.134 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1b3ba25 18:43:53.129 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.138 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:53.138 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.145 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to PING 18:43:53.144 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.150 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:53.151 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.156 [DEBUG] [andclass.ZWaveNoOperationCommandClass] - NODE 3: Creating new message for command NO_OPERATION_PING 18:43:53.159 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary for OnOffType 18:43:53.166 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:53.169 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary for OnOffType 18:43:53.170 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:53.175 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured 18:43:53.179 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@8eb01e 18:43:53.180 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_temperature for QuantityType 18:43:53.183 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:53.185 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_temperature for QuantityType 18:43:53.187 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 11 to queue - size 2 18:43:53.191 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.192 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_kwh for DecimalType 18:43:53.196 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 03 01 00 25 01 C2 18:43:53.197 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_kwh for DecimalType 18:43:53.200 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 08 00 13 03 01 00 25 01 C2 18:43:53.202 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_watts for DecimalType 18:43:53.205 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:53.204 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:53.209 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.208 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_watts for DecimalType 18:43:53.211 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 11: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 1 18:43:53.215 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:53.215 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.217 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_reset for OnOffType 18:43:53.223 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 11: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 1 18:43:53.226 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_reset for OnOffType 18:43:53.223 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.227 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:53.234 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 01 00 00 02 E8 18:43:53.238 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.240 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=1, payload=01 00 00 02 18:43:53.242 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 11: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 1 18:43:53.246 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.251 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 11: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 1 18:43:53.255 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.261 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general for OnOffType 18:43:53.261 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:53.264 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general for OnOffType 18:43:53.266 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 11: Advanced to WAIT_REQUEST 18:43:53.268 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_binary1 for OnOffType 18:43:53.270 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 11: Transaction not completed 18:43:53.272 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_binary1 for OnOffType 18:43:53.277 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=1, payload=01 00 00 02 18:43:53.279 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer1 for OnOffType 18:43:53.280 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 11: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 1 18:43:53.282 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.284 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.286 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.288 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 11: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 1 18:43:53.290 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.292 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 11: (Callback 1) 18:43:53.294 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_kwh1 for DecimalType 18:43:53.296 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:53.297 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_kwh1 for DecimalType 18:43:53.300 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 11: callback 1 18:43:53.302 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_watts1 for DecimalType 18:43:53.304 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=1, payload=01 00 00 02 18:43:53.306 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_watts1 for DecimalType 18:43:53.310 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.311 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 1, Status = Transmission complete and ACK received(0) 18:43:53.313 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.316 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 11: Transaction COMPLETED 18:43:53.319 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.320 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 109ms 18:43:53.323 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_temperature2 for QuantityType 18:43:53.324 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 11: Transaction completed 18:43:53.328 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_temperature2 for QuantityType 18:43:53.329 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:11 DONE 18:43:53.333 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general2 for OnOffType 18:43:53.334 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:53.334 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 11: Transaction event listener: DONE: DONE -> 18:43:53.337 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general2 for OnOffType 18:43:53.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.343 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@17a1226 18:43:53.347 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.346 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.349 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:53.354 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.355 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to REQUEST_NIF 18:43:53.359 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.359 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:53.363 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general3 for OnOffType 18:43:53.368 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general3 for OnOffType 18:43:53.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@17aef3e 18:43:53.377 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 1800 seconds - start in 1026000 milliseconds. 18:43:53.380 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:53.381 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete. 18:43:53.383 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 12 to queue - size 2 18:43:53.387 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.391 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 03 98 18:43:53.394 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 03 98 18:43:53.398 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:53.400 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:53.401 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 12: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.402 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.407 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.408 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 18:43:53.410 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 12: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 18:43:53.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:53.419 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 18:43:53.422 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 12: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.424 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 12: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 18:43:53.430 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 18:43:53.433 [DEBUG] [almessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack. 18:43:53.436 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 12: Advanced to WAIT_DATA 18:43:53.438 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 12: Transaction not completed 18:43:53.441 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.444 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:53.549 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1A 00 49 84 03 14 04 11 01 5E 86 5A 72 73 27 25 26 32 71 85 8E 59 70 EF 20 26 04 18:43:53.558 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 14 04 11 01 5E 86 5A 72 73 27 25 26 32 71 85 8E 59 70 EF 20 26 18:43:53.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 14 04 11 01 5E 86 5A 72 73 27 25 26 32 71 85 8E 59 70 EF 20 26 18:43:53.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 12: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0 18:43:53.569 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.572 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 12: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0 18:43:53.575 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 12: (Callback 0) 18:43:53.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 12: callback 0 18:43:53.585 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 14 04 11 01 5E 86 5A 72 73 27 25 26 32 71 85 8E 59 70 EF 20 26 18:43:53.588 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction TID 12: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0 18:43:53.591 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 12: Transaction COMPLETED 18:43:53.596 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 194ms 18:43:53.598 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 12: Transaction completed 18:43:53.601 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:12 DONE 18:43:53.604 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 12: Transaction event listener: DONE: DONE -> 18:43:53.604 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:53.612 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@16413a3 18:43:53.615 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.615 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:53.618 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.619 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Restored from file - skipping static initialisation 18:43:53.623 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to STATIC_END 18:43:53.626 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:53.629 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. 18:43:53.631 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=345 18:43:53.634 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=345. SET. Was 345 18:43:53.637 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised 18:43:53.645 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.648 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[node_3]]: Adding node_3 18:43:53.651 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[node_3]]: Adding node_3 18:43:53.654 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=6, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.657 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=7, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.660 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=9, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.663 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=10, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 18:43:53.667 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node... 18:43:53.671 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_binary for OnOffType 18:43:53.674 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_binary for OnOffType 18:43:53.678 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer for OnOffType 18:43:53.681 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.684 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.688 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer for PercentType 18:43:53.691 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary for OnOffType 18:43:53.694 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary for OnOffType 18:43:53.698 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_temperature for QuantityType 18:43:53.701 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_temperature for QuantityType 18:43:53.704 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_kwh for DecimalType 18:43:53.707 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_kwh for DecimalType 18:43:53.710 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_watts for DecimalType 18:43:53.713 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_watts for DecimalType 18:43:53.716 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_reset for OnOffType 18:43:53.719 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_reset for OnOffType 18:43:53.722 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general for OnOffType 18:43:53.724 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general for OnOffType 18:43:53.728 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_binary1 for OnOffType 18:43:53.730 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_binary1 for OnOffType 18:43:53.734 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer1 for OnOffType 18:43:53.737 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.739 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.742 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:switch_dimmer1 for PercentType 18:43:53.746 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_kwh1 for DecimalType 18:43:53.749 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_kwh1 for DecimalType 18:43:53.752 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:meter_watts1 for DecimalType 18:43:53.755 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:meter_watts1 for DecimalType 18:43:53.758 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.761 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.764 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary2 for OnOffType 18:43:53.768 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_temperature2 for QuantityType 18:43:53.771 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_temperature2 for QuantityType 18:43:53.774 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general2 for OnOffType 18:43:53.777 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general2 for OnOffType 18:43:53.780 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.783 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.786 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:sensor_binary3 for OnOffType 18:43:53.789 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:a94d59a1:node3:alarm_general3 for OnOffType 18:43:53.792 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:a94d59a1:node3:alarm_general3 for OnOffType 18:43:53.795 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 1800 seconds - start in 160200 milliseconds. 18:43:53.798 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serialise aborted as static stages not complete 18:43:53.800 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to DYNAMIC_VALUES 18:43:53.803 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:53.806 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_METER 18:43:53.808 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Found 1 instances of COMMAND_CLASS_METER for endpoint 0 18:43:53.811 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 3: Creating new message for application command METER_GET 18:43:53.816 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 3: Creating new message for application command METER_GET 18:43:53.819 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:53.822 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_METER is NOT required to be secured 18:43:53.824 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:53.827 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:53.829 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_METER is NOT required to be secured 18:43:53.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@12c8dde 18:43:53.835 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:53.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 13 to queue - size 2 18:43:53.840 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:53.844 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 32 01 10 25 02 E2 18:43:53.850 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 32 01 10 25 02 E2 18:43:53.853 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:53.856 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:53.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 2 18:43:53.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:53.864 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:53.866 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 13: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 2 18:43:53.870 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:53.870 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.873 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.877 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:53.879 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.882 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 13: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 2 18:43:53.883 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 02 00 00 03 EA 18:43:53.885 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 13: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 2 18:43:53.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=2, payload=02 00 00 03 18:43:53.891 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:53.894 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:53.896 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 13: Advanced to WAIT_REQUEST 18:43:53.899 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 13: Transaction not completed 18:43:53.902 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=2, payload=02 00 00 03 18:43:53.905 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 13: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 2 18:43:53.908 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:53.910 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 13: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 2 18:43:53.912 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 13: (Callback 2) 18:43:53.914 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:53.917 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 13: callback 2 18:43:53.920 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=2, payload=02 00 00 03 18:43:53.923 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 2, Status = Transmission complete and ACK received(0) 18:43:53.926 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 13: Advanced to WAIT_DATA 18:43:53.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 13: Transaction not completed 18:43:53.931 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:53.933 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:53.937 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 C7 18:43:53.943 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 18:43:53.947 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 18:43:53.949 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:53.951 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES) 18:43:53.955 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0 18:43:53.957 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:53.960 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT 18:43:53.969 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=W(2), Value=0E+1 18:43:53.972 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent 18:43:53.974 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1 18:43:53.979 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:meter_watts to 0 [DecimalType] 18:43:53.982 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:43:53.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@ccbc1e. 18:43:53.988 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@ccbc1e. 18:43:53.991 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:13 DONE 18:43:53.994 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 13: Transaction event listener: DONE: DONE -> 18:43:53.994 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:53.999 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@607813 18:43:54.003 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:54.004 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:43:54.006 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.009 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:43:54.010 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_METER is NOT required to be secured 18:43:54.014 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.015 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:54.018 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.019 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.025 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_METER is NOT required to be secured 18:43:54.028 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@ef7549 18:43:54.032 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:54.036 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 14 to queue - size 2 18:43:54.040 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.046 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 32 01 00 25 03 F3 18:43:54.051 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 32 01 00 25 03 F3 18:43:54.056 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:54.058 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:54.061 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 14: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 3 18:43:54.064 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.070 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.071 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:54.074 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 14: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 3 18:43:54.078 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.080 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:54.086 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.087 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 03 00 00 02 EA 18:43:54.091 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 14: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 3 18:43:54.096 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=3, payload=03 00 00 02 18:43:54.097 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.104 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 14: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 3 18:43:54.108 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.113 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:54.117 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 14: Advanced to WAIT_REQUEST 18:43:54.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 14: Transaction not completed 18:43:54.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=3, payload=03 00 00 02 18:43:54.128 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 14: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 3 18:43:54.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.133 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 14: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 3 18:43:54.136 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 14: (Callback 3) 18:43:54.140 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:54.142 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 14: callback 3 18:43:54.146 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=3, payload=03 00 00 02 18:43:54.148 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 03 0E 32 02 21 24 00 00 01 3F 00 00 00 00 00 00 E9 18:43:54.149 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 3, Status = Transmission complete and ACK received(0) 18:43:54.153 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 14: Advanced to WAIT_DATA 18:43:54.155 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 24 00 00 01 3F 00 00 00 00 00 00 18:43:54.157 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 14: Transaction not completed 18:43:54.161 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 24 00 00 01 3F 00 00 00 00 00 00 18:43:54.164 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:54.167 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES) 18:43:54.170 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0 18:43:54.173 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.176 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT 18:43:54.180 [DEBUG] [l.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=kWh(0), Value=31.9 18:43:54.183 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent 18:43:54.186 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=31.9 18:43:54.190 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:meter_kwh to 31.9 [DecimalType] 18:43:54.194 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:43:54.196 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@154d3ca. 18:43:54.199 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@154d3ca. 18:43:54.202 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:14 DONE 18:43:54.206 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 14: Transaction event listener: DONE: DONE -> 18:43:54.206 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:54.215 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@12b7010 18:43:54.217 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:43:54.219 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:54.221 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:43:54.223 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION 18:43:54.225 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.228 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ASSOCIATION 18:43:54.229 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.232 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ZWAVEPLUS_INFO 18:43:54.236 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MULTI_CHANNEL 18:43:54.246 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_NO_OPERATION 18:43:54.248 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ASSOCIATION_GRP_INFO 18:43:54.251 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SWITCH_ALL 18:43:54.253 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MANUFACTURER_SPECIFIC 18:43:54.256 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_VERSION 18:43:54.258 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_POWERLEVEL 18:43:54.261 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Found 1 instances of COMMAND_CLASS_POWERLEVEL for endpoint 0 18:43:54.263 [DEBUG] [mandclass.ZWavePowerLevelCommandClass] - NODE 3: Creating new message for application command POWERLEVEL_GET 18:43:54.266 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.269 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured 18:43:54.271 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:54.274 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.277 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_POWERLEVEL is NOT required to be secured 18:43:54.279 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@365f16 18:43:54.282 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:54.285 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 15 to queue - size 2 18:43:54.287 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.291 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 73 02 25 04 B4 18:43:54.294 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 73 02 25 04 B4 18:43:54.297 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:54.299 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:54.300 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 15: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 4 18:43:54.302 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.305 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.306 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:54.309 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 15: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 4 18:43:54.311 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.313 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:54.317 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.320 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 15: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 4 18:43:54.323 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.326 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 15: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 4 18:43:54.327 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 04 00 00 02 ED 18:43:54.331 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.333 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 02 18:43:54.335 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:54.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 15: Advanced to WAIT_REQUEST 18:43:54.340 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 03 04 73 03 00 00 86 18:43:54.341 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 15: Transaction not completed 18:43:54.345 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 02 18:43:54.345 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 04 73 03 00 00 18:43:54.348 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 15: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 4 18:43:54.352 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.354 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 15: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 4 18:43:54.357 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 15: (Callback 4) 18:43:54.359 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:54.362 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 15: callback 4 18:43:54.364 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 02 18:43:54.367 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 4, Status = Transmission complete and ACK received(0) 18:43:54.370 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 15: Advanced to WAIT_DATA 18:43:54.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 15: Transaction not completed 18:43:54.375 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 04 73 03 00 00 18:43:54.377 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:54.380 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES) 18:43:54.382 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_POWERLEVEL, endpoint 0 18:43:54.385 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.387 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_POWERLEVEL V1 POWERLEVEL_REPORT 18:43:54.390 [DEBUG] [mandclass.ZWavePowerLevelCommandClass] - NODE 3: Received POWERLEVEL report -0dB with 0 second timeout 18:43:54.393 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWavePowerLevelCommandClassChangeEvent 18:43:54.396 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_POWERLEVEL, value=0 18:43:54.399 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:43:54.401 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@ffb0cb. 18:43:54.404 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@ffb0cb. 18:43:54.406 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:15 DONE 18:43:54.409 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 15: Transaction event listener: DONE: DONE -> 18:43:54.409 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:54.415 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@11b04a3 18:43:54.417 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:43:54.419 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:54.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:43:54.422 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SWITCH_BINARY 18:43:54.424 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.426 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Found 1 instances of COMMAND_CLASS_SWITCH_BINARY for endpoint 0 18:43:54.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.430 [DEBUG] [ndclass.ZWaveBinarySwitchCommandClass] - NODE 3: Creating new message for application command SWITCH_BINARY_GET 18:43:54.434 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.437 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 18:43:54.440 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:54.443 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.446 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 18:43:54.449 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@ff7634 18:43:54.452 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:54.455 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 16 to queue - size 2 18:43:54.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.461 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 25 02 25 05 E3 18:43:54.464 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 25 02 25 05 E3 18:43:54.467 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:54.470 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:54.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 16: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 5 18:43:54.474 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.478 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.479 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:54.480 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 16: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 5 18:43:54.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:54.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.487 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.490 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:43:54.493 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.496 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 05 00 00 02 EC 18:43:54.496 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 16: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 5 18:43:54.500 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 02 18:43:54.501 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.505 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 16: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 5 18:43:54.507 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.510 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:54.512 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 16: Advanced to WAIT_REQUEST 18:43:54.515 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 16: Transaction not completed 18:43:54.518 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 02 18:43:54.521 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 16: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 5 18:43:54.523 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.526 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 16: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 5 18:43:54.528 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 16: (Callback 5) 18:43:54.530 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 25 03 00 D4 18:43:54.531 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:54.535 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 16: callback 5 18:43:54.535 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 25 03 00 18:43:54.538 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 02 18:43:54.541 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 5, Status = Transmission complete and ACK received(0) 18:43:54.544 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 16: Advanced to WAIT_DATA 18:43:54.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 16: Transaction not completed 18:43:54.549 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 25 03 00 18:43:54.552 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:54.554 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES) 18:43:54.557 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0 18:43:54.559 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.562 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT 18:43:54.565 [DEBUG] [ndclass.ZWaveBinarySwitchCommandClass] - NODE 3: Switch Binary report, value = 0 18:43:54.568 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 18:43:54.571 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0 18:43:54.574 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:switch_binary to OFF [OnOffType] 18:43:54.577 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:43:54.580 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@104f1df. 18:43:54.582 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@104f1df. 18:43:54.585 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:16 DONE 18:43:54.588 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 16: Transaction event listener: DONE: DONE -> 18:43:54.588 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:54.593 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@8a330b 18:43:54.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:43:54.596 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:54.598 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:43:54.599 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_DEVICE_RESET_LOCALLY 18:43:54.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.603 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_SWITCH_MULTILEVEL 18:43:54.606 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.607 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Found 1 instances of COMMAND_CLASS_SWITCH_MULTILEVEL for endpoint 0 18:43:54.610 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_GET 18:43:54.613 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.616 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:43:54.619 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 18:43:54.622 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.624 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:43:54.627 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@2c17e3 18:43:54.630 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:43:54.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 17 to queue - size 2 18:43:54.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.638 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 26 02 25 06 E3 18:43:54.641 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 26 02 25 06 E3 18:43:54.643 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:43:54.646 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:43:54.646 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 17: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 6 18:43:54.649 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:43:54.653 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:43:54.655 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 6 18:43:54.657 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.658 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:43:54.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.665 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 6 18:43:54.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.671 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 17: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 6 18:43:54.673 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 06 00 00 03 EE 18:43:54.674 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:43:54.677 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=6, payload=06 00 00 03 18:43:54.680 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:43:54.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 17: Advanced to WAIT_REQUEST 18:43:54.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 17: Transaction not completed 18:43:54.690 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=6, payload=06 00 00 03 18:43:54.692 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 6 18:43:54.695 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:43:54.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 17: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 6 18:43:54.701 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 17: (Callback 6) 18:43:54.703 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:43:54.707 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 17: callback 6 18:43:54.707 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 26 03 00 D7 18:43:54.709 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=6, payload=06 00 00 03 18:43:54.712 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 18:43:54.713 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 6, Status = Transmission complete and ACK received(0) 18:43:54.717 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 17: Advanced to WAIT_DATA 18:43:54.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 17: Transaction not completed 18:43:54.723 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 18:43:54.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:43:54.729 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DYNAMIC_VALUES) 18:43:54.732 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 18:43:54.734 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:43:54.737 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT 18:43:54.740 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Switch Multi Level report, value = 0 18:43:54.743 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 18:43:54.746 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0 18:43:54.750 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:switch_dimmer to 0 [PercentType] 18:43:54.755 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:43:54.758 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@144c7fe. 18:43:54.761 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@144c7fe. 18:43:54.764 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:17 DONE 18:43:54.767 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 17: Transaction event listener: DONE: DONE -> 18:43:54.767 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:43:54.776 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@19d3d59 18:43:54.776 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:43:54.781 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:43:54.779 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 18:43:54.784 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:43:54.786 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BASIC 18:43:54.788 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:43:54.790 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_CONFIGURATION 18:43:54.794 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ALARM 18:43:54.797 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Found 1 instances of COMMAND_CLASS_ALARM for endpoint 0 18:43:54.800 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Initialisation complete! 18:43:54.803 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to DYNAMIC_END 18:43:54.806 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:54.810 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serializing to file /openhab/userdata/zwave/network_defd38d5__node_3.xml 18:43:54.847 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to DONE 18:43:54.850 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 18:43:54.856 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serializing to file /openhab/userdata/zwave/network_defd38d5__node_3.xml 18:44:06.673 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:a94d59a1:node3:switch_dimmer --> 100 [PercentType] 18:44:06.679 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_SET 18:44:06.684 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:06.688 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:44:06.695 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:44:06.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 18 to queue - size 2 18:44:06.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:06.709 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 26 01 63 25 07 80 18:44:06.715 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 26 01 63 25 07 80 18:44:06.720 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:44:06.721 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:44:06.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 18: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 7 18:44:06.727 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:06.734 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 1800 seconds - start in 1500 milliseconds. 18:44:06.735 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:06.739 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 18: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 7 18:44:06.740 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:44:06.743 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:44:06.749 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:06.749 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:06.753 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:44:06.758 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:06.758 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 07 00 00 03 EF 18:44:06.761 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 18: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 7 18:44:06.765 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:06.765 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 03 18:44:06.768 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 18: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 7 18:44:06.772 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:06.774 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:44:06.777 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 18: Advanced to WAIT_REQUEST 18:44:06.780 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 18: Transaction not completed 18:44:06.782 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 03 18:44:06.785 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 18: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 7 18:44:06.788 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:06.791 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 18: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 7 18:44:06.794 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 18: (Callback 7) 18:44:06.797 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:44:06.799 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 18: callback 7 18:44:06.802 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=7, payload=07 00 00 03 18:44:06.805 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 7, Status = Transmission complete and ACK received(0) 18:44:06.808 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:06.810 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 18: Transaction COMPLETED 18:44:06.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 88ms 18:44:06.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 18: Transaction completed 18:44:06.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:18 DONE 18:44:06.827 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:44:06.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:06.833 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:07.250 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 03 08 60 0D 01 00 26 01 63 00 D6 18:44:07.256 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 08 60 0D 01 00 26 01 63 00 18:44:07.260 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 08 60 0D 01 00 26 01 63 00 18:44:07.263 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:44:07.265 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE) 18:44:07.268 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:07.271 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 18:44:07.274 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: No endpoint 1! 18:44:07.276 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:07.279 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:08.234 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling... 18:44:08.240 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:a94d59a1:node3:switch_dimmer 18:44:08.246 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 3: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 18:44:08.251 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_GET 18:44:08.258 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:08.262 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:44:08.269 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:a94d59a1:node3:switch_dimmer on COMMAND_CLASS_BASIC 18:44:08.273 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:a94d59a1:node3:sensor_binary3 18:44:08.278 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:a94d59a1:node3:sensor_binary3 on COMMAND_CLASS_BASIC 18:44:08.282 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:44:08.287 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 19 to queue - size 2 18:44:08.291 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:08.296 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 26 02 25 08 ED 18:44:08.300 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 26 02 25 08 ED 18:44:08.307 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:44:08.306 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:44:08.316 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 19: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 8 18:44:08.317 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:08.324 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:08.325 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:44:08.327 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 19: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 8 18:44:08.332 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:44:08.333 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:08.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:08.342 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:44:08.343 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 08 00 00 02 E1 18:44:08.346 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:08.352 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 19: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 8 18:44:08.353 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=8, payload=08 00 00 02 18:44:08.357 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:08.363 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 19: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 8 18:44:08.368 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:08.369 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 26 03 63 B4 18:44:08.371 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:44:08.375 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 19: Advanced to WAIT_REQUEST 18:44:08.375 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 63 18:44:08.378 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 19: Transaction not completed 18:44:08.382 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=SendData[19], type=Request[0], dest=0, callback=8, payload=08 00 00 02 18:44:08.385 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 19: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 8 18:44:08.387 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:08.390 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 19: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 8 18:44:08.393 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 19: (Callback 8) 18:44:08.396 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:44:08.398 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 19: callback 8 18:44:08.401 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=8, payload=08 00 00 02 18:44:08.404 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 8, Status = Transmission complete and ACK received(0) 18:44:08.407 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:08.410 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 19: Advanced to WAIT_DATA 18:44:08.413 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 19: Transaction not completed 18:44:08.416 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 63 18:44:08.419 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:44:08.421 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE) 18:44:08.425 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:08.428 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 18:44:08.430 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:08.433 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT 18:44:08.437 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Switch Multi Level report, value = 99 18:44:08.439 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 18:44:08.442 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=99 18:44:08.445 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:switch_dimmer to 100 [PercentType] 18:44:08.450 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:44:08.453 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3e53b5. 18:44:08.456 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3e53b5. 18:44:08.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:19 DONE 18:44:08.461 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:44:08.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:44:08.469 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:44:08.472 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:08.474 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:14.874 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:a94d59a1:node3:switch_dimmer --> 0 [PercentType] 18:44:14.878 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_SET 18:44:14.882 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:14.886 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:44:14.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:44:14.894 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 20 to queue - size 2 18:44:14.897 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:14.902 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 26 01 00 25 09 ED 18:44:14.906 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 26 01 00 25 09 ED 18:44:14.910 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:44:14.913 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:44:14.914 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 20: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 9 18:44:14.917 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:14.920 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 1800 seconds - start in 1500 milliseconds. 18:44:14.921 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:14.925 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 9 18:44:14.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:44:14.931 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:14.934 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:44:14.923 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:44:14.946 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:14.950 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:14.951 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 09 00 00 03 E1 18:44:14.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 9 18:44:14.956 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:14.956 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=9, payload=09 00 00 03 18:44:14.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 20: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 9 18:44:14.963 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:14.966 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:44:14.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 20: Advanced to WAIT_REQUEST 18:44:14.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 20: Transaction not completed 18:44:14.973 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=9, payload=09 00 00 03 18:44:14.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 9 18:44:14.979 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:14.981 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 20: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 9 18:44:14.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 20: (Callback 9) 18:44:14.986 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:44:14.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 20: callback 9 18:44:14.991 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=9, payload=09 00 00 03 18:44:14.994 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 9, Status = Transmission complete and ACK received(0) 18:44:14.997 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:15.000 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 20: Transaction COMPLETED 18:44:15.003 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 88ms 18:44:15.005 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 20: Transaction completed 18:44:15.008 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:20 DONE 18:44:15.011 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:44:15.020 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:15.023 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:15.419 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 03 08 60 0D 01 00 26 01 00 00 B5 18:44:15.423 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 08 60 0D 01 00 26 01 00 00 18:44:15.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 08 60 0D 01 00 26 01 00 00 18:44:15.430 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:44:15.432 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE) 18:44:15.435 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:15.438 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 18:44:15.441 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: No endpoint 1! 18:44:15.443 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:15.446 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:16.420 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling... 18:44:16.423 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:a94d59a1:node3:switch_dimmer 18:44:16.437 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 3: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 18:44:16.439 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_GET 18:44:16.443 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:16.445 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 18:44:16.457 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:a94d59a1:node3:switch_dimmer on COMMAND_CLASS_BASIC 18:44:16.460 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:a94d59a1:node3:sensor_binary3 18:44:16.464 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:a94d59a1:node3:sensor_binary3 on COMMAND_CLASS_BASIC 18:44:16.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 18:44:16.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 21 to queue - size 2 18:44:16.473 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:16.477 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 26 02 25 0A EF 18:44:16.480 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 26 02 25 0A EF 18:44:16.483 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT 18:44:16.485 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 18:44:16.489 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 21: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 10 18:44:16.491 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:16.495 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 18:44:16.496 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 18:44:16.498 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 10 18:44:16.502 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK 18:44:16.501 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:16.504 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:16.508 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 18:44:16.511 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:16.512 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0A 00 00 03 E2 18:44:16.514 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 10 18:44:16.518 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:16.519 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=10, payload=0A 00 00 03 18:44:16.521 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 21: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 10 18:44:16.525 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 18:44:16.528 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack. 18:44:16.531 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 21: Advanced to WAIT_REQUEST 18:44:16.534 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 21: Transaction not completed 18:44:16.536 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=10, payload=0A 00 00 03 18:44:16.539 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 10 18:44:16.541 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 18:44:16.544 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 21: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 10 18:44:16.546 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 21: (Callback 10) 18:44:16.547 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 26 03 00 D7 18:44:16.549 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match! 18:44:16.553 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 21: callback 10 18:44:16.554 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 18:44:16.556 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=10, payload=0A 00 00 03 18:44:16.561 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 10, Status = Transmission complete and ACK received(0) 18:44:16.563 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:16.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 21: Advanced to WAIT_DATA 18:44:16.569 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 21: Transaction not completed 18:44:16.571 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 18:44:16.574 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null 18:44:16.577 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE) 18:44:16.579 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 18:44:16.582 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 18:44:16.584 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported 18:44:16.587 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT 18:44:16.590 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Switch Multi Level report, value = 0 18:44:16.592 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 18:44:16.595 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0 18:44:16.599 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:a94d59a1:node3:switch_dimmer to 0 [PercentType] 18:44:16.603 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 18:44:16.606 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ed564. 18:44:16.609 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ed564. 18:44:16.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:21 DONE 18:44:16.620 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 18:44:16.622 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 18:44:16.626 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 18:44:16.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 18:44:16.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 18:44:18.451 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener. 18:44:18.491 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 3: Serializing to file /openhab/userdata/zwave/network_defd38d5__node_3.xml 18:44:18.585 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Disposing receive thread 18:44:18.836 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive 18:44:18.839 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Receive thread dispose 18:44:18.842 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Disposing serial connection 18:44:18.891 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Serial connection disposed 18:44:18.894 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler 18:44:18.897 [DEBUG] [ave.internal.protocol.ZWaveController] - Shutting down ZWave controller 18:44:18.900 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Shutting down transaction manager 18:44:18.903 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Exiting ZWave Receive Thread 18:44:23.617 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Deactivate zwave:serial_zstick:a94d59a1 18:44:23.906 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWave Transaction manager failed to terminate properly, forcing shutdown 18:44:23.909 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction manager shutdown 18:44:23.910 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction exception java.util.concurrent.ExecutionException: java.lang.InterruptedException at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:1.8.0_232] at java.util.concurrent.FutureTask.get(FutureTask.java:192) ~[?:1.8.0_232] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:442) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.access$6(ZWaveNodeInitStageAdvancer.java:373) [bundleFile:?] at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?] Caused by: java.lang.InterruptedException at java.lang.Object.wait(Native Method) ~[?:1.8.0_232] at java.lang.Object.wait(Object.java:502) ~[?:1.8.0_232] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?] at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_232] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_232] at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_232] 18:44:23.926 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response null 18:44:23.928 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 2: Skipping initialization thread, process stopped by controller 18:44:23.931 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller shutdown 18:44:35.545 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:a94d59a1 with scan time of 60 18:44:35.549 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:a94d59a1 18:44:35.553 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null 18:44:35.863 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 18:44:35.867 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:a94d59a1. 18:44:36.013 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:a94d59a1:node3. 18:44:36.021 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:a94d59a1:node3:switch_dimmer linked - polling started. 18:44:36.022 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:a94d59a1:node3:sensor_binary3 linked - polling started.