2020-02-11 14:05:17.522 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.524 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.531 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Handler disposed. Unregistering listener. 2020-02-11 14:05:17.543 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 13: Serialise aborted as static stages not complete ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.552 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.555 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from ONLINE to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.561 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Handler disposed. Unregistering listener. 2020-02-11 14:05:17.572 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Serializing to file /var/lib/openhab2/zwave/network_e5a7b0ac__node_2.xml ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.595 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.597 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from ONLINE to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.604 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener. 2020-02-11 14:05:17.615 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serializing to file /var/lib/openhab2/zwave/network_e5a7b0ac__node_3.xml ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.635 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.637 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.646 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Handler disposed. Unregistering listener. 2020-02-11 14:05:17.656 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 12: Serialise aborted as static stages not complete ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.663 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.667 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.674 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Handler disposed. Unregistering listener. 2020-02-11 14:05:17.685 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 10: Serialise aborted as static stages not complete ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.692 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:17.694 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:cf541806' changed from ONLINE to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:17.703 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread 2020-02-11 14:05:17.736 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive 2020-02-11 14:05:17.776 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose 2020-02-11 14:05:17.777 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection 2020-02-11 14:05:17.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed 2020-02-11 14:05:17.783 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler 2020-02-11 14:05:17.784 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller 2020-02-11 14:05:17.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager 2020-02-11 14:05:17.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Exiting ZWave Receive Thread 2020-02-11 14:05:17.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction manager shutdown 2020-02-11 14:05:17.788 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init transaction completed with response null 2020-02-11 14:05:17.789 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Skipping initialization thread, process stopped by controller 2020-02-11 14:05:17.790 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node Init transaction completed with response null 2020-02-11 14:05:17.790 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Skipping initialization thread, process stopped by controller 2020-02-11 14:05:17.791 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init transaction completed with response null 2020-02-11 14:05:17.792 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Skipping initialization thread, process stopped by controller 2020-02-11 14:05:17.792 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init transaction completed with response null 2020-02-11 14:05:17.793 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Skipping initialization thread, process stopped by controller 2020-02-11 14:05:17.794 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init transaction completed with response null 2020-02-11 14:05:17.795 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Skipping initialization thread, process stopped by controller 2020-02-11 14:05:17.796 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller shutdown 2020-02-11 14:05:17.799 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Deactivate zwave:serial_zstick:cf541806 ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:17.805 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:cf541806' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2020-02-11 14:05:22.735 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED) ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.735 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:cf541806 with scan time of 60 ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.737 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED) ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.737 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:cf541806 ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.737 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED) ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.737 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.744 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED) 2020-02-11 14:05:22.804 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:cf541806' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.812 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller. 2020-02-11 14:05:22.813 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:cf541806. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.815 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:cf541806' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline 2020-02-11 14:05:22.835 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.845 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node12. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.848 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline 2020-02-11 14:05:22.955 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING 2020-02-11 14:05:22.956 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING 2020-02-11 14:05:22.957 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING 2020-02-11 14:05:22.959 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING 2020-02-11 14:05:22.964 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.969 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node2. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.972 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.973 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node10. 2020-02-11 14:05:22.976 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node13. 2020-02-11 14:05:22.978 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node3. 2020-02-11 14:05:22.978 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:cf541806:node2:sensor_temperature linked - polling started. 2020-02-11 14:05:22.979 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:cf541806:node2:sensor_luminance linked - polling started. 2020-02-11 14:05:22.981 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:cf541806:node2:sensor_relhumidity linked - polling started. 2020-02-11 14:05:22.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:cf541806:node2:battery-level linked - polling started. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.983 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.985 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:cf541806:node10:alarm_flood linked - polling started. 2020-02-11 14:05:22.986 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:cf541806:node10:battery-level linked - polling started. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.987 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline 2020-02-11 14:05:22.988 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:22.989 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:cf541806:node3:meter_voltage linked - polling started. 2020-02-11 14:05:22.990 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:cf541806:node15. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:22.994 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:27.839 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0' 2020-02-11 14:05:27.850 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread 2020-02-11 14:05:27.853 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized 2020-02-11 14:05:27.853 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive 2020-02-11 14:05:27.856 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller 2020-02-11 14:05:27.860 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller 2020-02-11 14:05:27.862 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false. 2020-02-11 14:05:27.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:27.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:27.867 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:27.872 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:27.875 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 12 hours time. 2020-02-11 14:05:30.867 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network 2020-02-11 14:05:30.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 373 to queue - size 1 2020-02-11 14:05:30.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:30.875 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 2020-02-11 14:05:30.877 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 2020-02-11 14:05:30.880 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:30.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 373: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.881 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:30.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 374 to queue - size 1 2020-02-11 14:05:30.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 373: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:30.887 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 34 2E 36 31 00 01 95 2020-02-11 14:05:30.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 375 to queue - size 2 2020-02-11 14:05:30.890 [DEBUG] [nal.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 36 31 00 01 2020-02-11 14:05:30.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.894 [DEBUG] [nal.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 36 31 00 01 2020-02-11 14:05:30.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 376 to queue - size 3 2020-02-11 14:05:30.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 373: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:30.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 373: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.901 [DEBUG] [ve.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 36 31 00 01 2020-02-11 14:05:30.901 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID 2020-02-11 14:05:30.902 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 4.61, Library Type=1 2020-02-11 14:05:30.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 377 to queue - size 4 2020-02-11 14:05:30.904 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 373: Transaction COMPLETED 2020-02-11 14:05:30.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 25ms 2020-02-11 14:05:30.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 373: Transaction completed 2020-02-11 14:05:30.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:373 DONE 2020-02-11 14:05:30.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:30.912 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 2020-02-11 14:05:30.914 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 2020-02-11 14:05:30.915 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:30.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 374: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.916 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:30.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 374: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.920 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 E5 A7 B0 AC 01 89 2020-02-11 14:05:30.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:30.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=E5 A7 B0 AC 01 2020-02-11 14:05:30.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=E5 A7 B0 AC 01 2020-02-11 14:05:30.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 374: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:30.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 374: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.930 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=E5 A7 B0 AC 01 2020-02-11 14:05:30.932 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xe5a7b0ac, Controller Node id = 1 2020-02-11 14:05:30.933 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 374: Transaction COMPLETED 2020-02-11 14:05:30.934 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 18ms 2020-02-11 14:05:30.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 374: Transaction completed 2020-02-11 14:05:30.936 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:374 DONE 2020-02-11 14:05:30.937 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:30.939 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 2020-02-11 14:05:30.941 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 2020-02-11 14:05:30.942 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:30.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 375: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.945 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:30.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.949 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 375: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.950 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:30.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.952 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00 52 2020-02-11 14:05:30.956 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00 2020-02-11 14:05:30.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00 2020-02-11 14:05:30.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 375: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:30.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 375: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.963 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00 2020-02-11 14:05:30.965 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version = 5.27 2020-02-11 14:05:30.966 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x115 2020-02-11 14:05:30.967 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type = 0x400 2020-02-11 14:05:30.968 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID = 0x1 2020-02-11 14:05:30.970 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 375: Transaction COMPLETED 2020-02-11 14:05:30.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 378 to queue - size 3 2020-02-11 14:05:30.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 31ms 2020-02-11 14:05:30.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 375: Transaction completed 2020-02-11 14:05:30.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:375 DONE 2020-02-11 14:05:30.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:30.980 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 2020-02-11 14:05:30.981 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 2020-02-11 14:05:30.982 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:30.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 376: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.984 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:30.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:30.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 376: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.988 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 2020-02-11 14:05:30.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:30.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:30.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2020-02-11 14:05:30.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:30.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2020-02-11 14:05:30.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 376: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:30.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 376: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:30.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 2020-02-11 14:05:30.998 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15 2020-02-11 14:05:30.999 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 376: Transaction COMPLETED 2020-02-11 14:05:31.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 17ms 2020-02-11 14:05:31.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 376: Transaction completed 2020-02-11 14:05:31.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:376 DONE 2020-02-11 14:05:31.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.006 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 2020-02-11 14:05:31.007 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 2020-02-11 14:05:31.008 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 377: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.010 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.012 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 01 AD 2020-02-11 14:05:31.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 377: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 377: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 377: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.018 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.019 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response. 2020-02-11 14:05:31.020 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - NODE 1: Node is SUC. 2020-02-11 14:05:31.020 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 377: Transaction COMPLETED 2020-02-11 14:05:31.021 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message 2020-02-11 14:05:31.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 379 to queue - size 2 2020-02-11 14:05:31.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 13ms 2020-02-11 14:05:31.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 377: Transaction completed 2020-02-11 14:05:31.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:377 DONE 2020-02-11 14:05:31.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.026 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 2020-02-11 14:05:31.026 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 2020-02-11 14:05:31.027 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 378: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.028 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 378: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.124 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 06 08 1D 97 5A 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 02 2020-02-11 14:05:31.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=06 08 1D 97 5A 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 2020-02-11 14:05:31.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=06 08 1D 97 5A 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 2020-02-11 14:05:31.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 378: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 378: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.129 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=06 08 1D 97 5A 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 2020-02-11 14:05:31.130 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response. 2020-02-11 14:05:31.130 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found 2020-02-11 14:05:31.131 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found 2020-02-11 14:05:31.131 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found 2020-02-11 14:05:31.132 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found 2020-02-11 14:05:31.132 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found 2020-02-11 14:05:31.133 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found 2020-02-11 14:05:31.133 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found 2020-02-11 14:05:31.134 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found 2020-02-11 14:05:31.134 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found 2020-02-11 14:05:31.135 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API 2020-02-11 14:05:31.136 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller 2020-02-11 14:05:31.136 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------ 2020-02-11 14:05:31.137 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 9 2020-02-11 14:05:31.137 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ---------------------------------------------------------------------------- 2020-02-11 14:05:31.138 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 378: Transaction COMPLETED 2020-02-11 14:05:31.138 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start 2020-02-11 14:05:31.139 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 8: Init node thread start 2020-02-11 14:05:31.139 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 3: Init node thread start 2020-02-11 14:05:31.139 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread start 2020-02-11 14:05:31.143 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 10: Init node thread start 2020-02-11 14:05:31.144 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Init node thread start 2020-02-11 14:05:31.145 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 13: Init node thread start 2020-02-11 14:05:31.145 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Init node thread start 2020-02-11 14:05:31.151 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 15: Init node thread start 2020-02-11 14:05:31.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 124ms 2020-02-11 14:05:31.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 378: Transaction completed 2020-02-11 14:05:31.153 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads 2020-02-11 14:05:31.154 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init 2020-02-11 14:05:31.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:378 DONE 2020-02-11 14:05:31.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.164 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 2020-02-11 14:05:31.165 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_1.xml 2020-02-11 14:05:31.165 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 2020-02-11 14:05:31.175 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 379: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.176 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.178 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 1C E3 2020-02-11 14:05:31.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.191 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_2.xml 2020-02-11 14:05:31.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 2020-02-11 14:05:31.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 379: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.191 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_3.xml 2020-02-11 14:05:31.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 2020-02-11 14:05:31.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 379: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 379: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.199 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=1C 2020-02-11 14:05:31.199 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 10: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_10.xml 2020-02-11 14:05:31.200 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false 2020-02-11 14:05:31.201 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 8: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_8.xml 2020-02-11 14:05:31.201 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false 2020-02-11 14:05:31.202 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false 2020-02-11 14:05:31.208 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true 2020-02-11 14:05:31.213 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 8: Error serializing from file: file does not exist. 2020-02-11 14:05:31.214 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.214 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = true 2020-02-11 14:05:31.217 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 8: Init node thread finished 2020-02-11 14:05:31.207 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Restore from config: Ok. 2020-02-11 14:05:31.226 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 379: Transaction COMPLETED 2020-02-11 14:05:31.226 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 51ms 2020-02-11 14:05:31.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 379: Transaction completed 2020-02-11 14:05:31.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:379 DONE 2020-02-11 14:05:31.213 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 12: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_12.xml 2020-02-11 14:05:31.228 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node advancer: Initialisation starting 2020-02-11 14:05:31.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@194dc11 2020-02-11 14:05:31.242 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 5: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_5.xml 2020-02-11 14:05:31.241 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 13: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_13.xml 2020-02-11 14:05:31.254 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 5: Error serializing from file: file does not exist. 2020-02-11 14:05:31.255 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.256 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.257 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 380 to queue - size 1 2020-02-11 14:05:31.265 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 3: Restore from config: Ok. 2020-02-11 14:05:31.266 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 5: Init node thread finished 2020-02-11 14:05:31.266 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 15: Serializing from file /var/lib/openhab2/zwave/network_e5a7b0ac__node_15.xml 2020-02-11 14:05:31.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.268 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 10: Restore from config: Ok. 2020-02-11 14:05:31.266 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.268 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.268 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 08 B2 2020-02-11 14:05:31.269 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.269 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 08 B2 2020-02-11 14:05:31.269 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer: Initialisation starting 2020-02-11 14:05:31.270 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.271 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created 2020-02-11 14:05:31.270 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.271 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.271 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.272 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.272 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_BATTERY, endpoint 0 created 2020-02-11 14:05:31.288 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created 2020-02-11 14:05:31.289 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.293 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_ALARM, endpoint 0 created 2020-02-11 14:05:31.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-02-11 14:05:31.294 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.298 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.299 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Restore from config: Ok. 2020-02-11 14:05:31.300 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.301 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_SENSOR_ALARM, endpoint 0 created 2020-02-11 14:05:31.301 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.286 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.285 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_METER, endpoint 0 created 2020-02-11 14:05:31.302 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting 2020-02-11 14:05:31.302 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0 created 2020-02-11 14:05:31.303 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@10b7937 2020-02-11 14:05:31.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 380: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.304 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created 2020-02-11 14:05:31.307 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.308 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.309 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.310 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_SECURITY, endpoint 0 created 2020-02-11 14:05:31.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1e9bec2 2020-02-11 14:05:31.311 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 10: Updated networkKey 2020-02-11 14:05:31.313 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 10: setupNetworkKey useSchemeZero=false 2020-02-11 14:05:31.315 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.316 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.317 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.318 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed 2020-02-11 14:05:31.318 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 15: Restore from config: Ok. 2020-02-11 14:05:31.319 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.320 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.320 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.321 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.322 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.299 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Restore from config: Ok. 2020-02-11 14:05:31.292 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished 2020-02-11 14:05:31.323 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.295 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 18 01 65 2020-02-11 14:05:31.324 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete 2020-02-11 14:05:31.324 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_SENSOR_BINARY, endpoint 0 created 2020-02-11 14:05:31.325 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.325 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.305 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.325 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.326 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.326 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 382 to queue - size 1 2020-02-11 14:05:31.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.327 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.323 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 381 to queue - size 2 2020-02-11 14:05:31.324 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_2_init 2020-02-11 14:05:31.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 380: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.328 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.328 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery resolved to thingType zwave:fibaro_fgfs101_03_002 2020-02-11 14:05:31.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.332 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ALARM, endpoint 0 created 2020-02-11 14:05:31.333 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.329 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.335 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.331 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created 2020-02-11 14:05:31.336 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 13: Restore from config: Ok. 2020-02-11 14:05:31.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 380: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.334 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.332 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_BATTERY, endpoint 0 created 2020-02-11 14:05:31.337 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_ZWAVEPLUS_INFO, endpoint 0 created 2020-02-11 14:05:31.337 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.338 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.338 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created 2020-02-11 14:05:31.338 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CLOCK, endpoint 0 created 2020-02-11 14:05:31.339 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.339 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created 2020-02-11 14:05:31.338 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.340 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: ProtocolInfo 2020-02-11 14:05:31.340 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Listening = false 2020-02-11 14:05:31.341 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Routing = true 2020-02-11 14:05:31.342 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Beaming = true 2020-02-11 14:05:31.343 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Version = 4 2020-02-11 14:05:31.343 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: FLIRS = false 2020-02-11 14:05:31.344 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Security = false 2020-02-11 14:05:31.345 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Max Baud = 40000 2020-02-11 14:05:31.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.346 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created 2020-02-11 14:05:31.346 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created 2020-02-11 14:05:31.346 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.347 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Generic = GENERIC_TYPE_WALL_CONTROLLER 2020-02-11 14:05:31.347 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.341 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.348 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 8: Specific = SPECIFIC_TYPE_BASIC_WALL_CONTROLLER 2020-02-11 14:05:31.348 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.349 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.349 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_ALARM, endpoint 0 created 2020-02-11 14:05:31.348 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created 2020-02-11 14:05:31.350 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_PROTECTION, endpoint 0 created 2020-02-11 14:05:31.351 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_BATTERY, endpoint 0 created 2020-02-11 14:05:31.351 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.351 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.349 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.352 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.352 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.350 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery completed 2020-02-11 14:05:31.353 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.353 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.354 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.356 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 380: Transaction COMPLETED 2020-02-11 14:05:31.356 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery resolved to thingType zwave:mcohome_a8co2_00_000 2020-02-11 14:05:31.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 84ms 2020-02-11 14:05:31.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 380: Transaction completed 2020-02-11 14:05:31.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:380 DONE 2020-02-11 14:05:31.345 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_BATTERY, endpoint 0 created 2020-02-11 14:05:31.359 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created 2020-02-11 14:05:31.359 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.360 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 10: Init node thread finished 2020-02-11 14:05:31.359 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.361 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.361 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created 2020-02-11 14:05:31.362 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SECURITY, endpoint 0 created 2020-02-11 14:05:31.362 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.363 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: Updated networkKey 2020-02-11 14:05:31.363 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 3: setupNetworkKey useSchemeZero=false 2020-02-11 14:05:31.360 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.364 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_ALARM, endpoint 0 created 2020-02-11 14:05:31.364 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.360 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.365 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_COLOR, endpoint 0 created 2020-02-11 14:05:31.364 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.366 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0 created 2020-02-11 14:05:31.364 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.366 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.367 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_ALARM, endpoint 0 created 2020-02-11 14:05:31.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.368 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.365 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer: Initialisation starting 2020-02-11 14:05:31.370 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 15: Init node thread finished 2020-02-11 14:05:31.365 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.371 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1675da4 2020-02-11 14:05:31.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 380: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.367 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.371 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SCENE_ACTUATOR_CONF, endpoint 0 created 2020-02-11 14:05:31.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.366 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created 2020-02-11 14:05:31.377 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@16cb761 2020-02-11 14:05:31.379 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.379 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created 2020-02-11 14:05:31.379 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 2020-02-11 14:05:31.380 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Node advancer - advancing to REQUEST_NIF 2020-02-11 14:05:31.380 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 2020-02-11 14:05:31.375 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer: Initialisation starting 2020-02-11 14:05:31.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1cc8584 2020-02-11 14:05:31.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_SENSOR_ALARM, endpoint 0 created 2020-02-11 14:05:31.378 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed 2020-02-11 14:05:31.378 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.378 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_SENSOR_ALARM, endpoint 0 created 2020-02-11 14:05:31.384 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.384 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed 2020-02-11 14:05:31.385 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.385 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.386 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0 created 2020-02-11 14:05:31.382 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.387 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.389 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 16 01 02 02 01 73 2020-02-11 14:05:31.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6e33e8 2020-02-11 14:05:31.387 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:aeon_zw100_01_010 2020-02-11 14:05:31.381 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.387 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created 2020-02-11 14:05:31.391 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_SECURITY, endpoint 0 created 2020-02-11 14:05:31.392 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 12: Updated networkKey 2020-02-11 14:05:31.392 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery resolved to thingType zwave:aeotec_zw175_00_000 2020-02-11 14:05:31.393 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 12: setupNetworkKey useSchemeZero=false 2020-02-11 14:05:31.395 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_VERSION, endpoint 0 created 2020-02-11 14:05:31.395 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.396 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.396 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.397 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.398 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery completed 2020-02-11 14:05:31.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Bump transaction 385 priority from Controller to Immediate 2020-02-11 14:05:31.398 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.399 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread finished 2020-02-11 14:05:31.400 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.400 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_2_init complete 2020-02-11 14:05:31.400 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_3_init 2020-02-11 14:05:31.401 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.400 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0 created 2020-02-11 14:05:31.402 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Initialisation starting 2020-02-11 14:05:31.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1c89d87 2020-02-11 14:05:31.404 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_SECURITY, endpoint 0 created 2020-02-11 14:05:31.405 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 13: Updated networkKey 2020-02-11 14:05:31.406 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 13: setupNetworkKey useSchemeZero=false 2020-02-11 14:05:31.407 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 3: Init node thread finished 2020-02-11 14:05:31.407 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created 2020-02-11 14:05:31.408 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created 2020-02-11 14:05:31.409 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created 2020-02-11 14:05:31.409 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.410 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery resolved to thingType zwave:fibaro_fgpb101_00_000 2020-02-11 14:05:31.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 381: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.411 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer: Initialisation starting 2020-02-11 14:05:31.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue 2020-02-11 14:05:31.411 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed 2020-02-11 14:05:31.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Added 385 to queue - size 1 2020-02-11 14:05:31.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2020-02-11 14:05:31.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@28c807 2020-02-11 14:05:31.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 384 to queue - size 2 2020-02-11 14:05:31.413 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_3_init complete 2020-02-11 14:05:31.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.419 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_5_init 2020-02-11 14:05:31.420 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_5_init complete 2020-02-11 14:05:31.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_8_init 2020-02-11 14:05:31.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_8_init complete 2020-02-11 14:05:31.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 383 to queue - size 3 2020-02-11 14:05:31.422 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_10_init 2020-02-11 14:05:31.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.422 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_10_init complete 2020-02-11 14:05:31.423 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_12_init 2020-02-11 14:05:31.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 386 to queue - size 4 2020-02-11 14:05:31.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 387 to queue - size 5 2020-02-11 14:05:31.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 381: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.431 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.436 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery resolved to thingType zwave:fibaro_fgpb101_00_000 2020-02-11 14:05:31.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2020-02-11 14:05:31.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 381: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 381: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.449 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 01 02 02 01 2020-02-11 14:05:31.450 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo 2020-02-11 14:05:31.451 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true 2020-02-11 14:05:31.452 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing = true 2020-02-11 14:05:31.452 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming = true 2020-02-11 14:05:31.453 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version = 4 2020-02-11 14:05:31.454 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS = false 2020-02-11 14:05:31.455 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security = false 2020-02-11 14:05:31.455 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud = 40000 2020-02-11 14:05:31.456 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic = BASIC_TYPE_STATIC_CONTROLLER 2020-02-11 14:05:31.457 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic = GENERIC_TYPE_STATIC_CONTROLLER 2020-02-11 14:05:31.458 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_PC_CONTROLLER 2020-02-11 14:05:31.458 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.459 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.460 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.461 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.462 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.463 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Init node thread finished 2020-02-11 14:05:31.463 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.464 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_12_init complete 2020-02-11 14:05:31.465 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_13_init 2020-02-11 14:05:31.467 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: Initialisation starting 2020-02-11 14:05:31.463 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@664fec 2020-02-11 14:05:31.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.469 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Starting initialisation from EMPTYNODE 2020-02-11 14:05:31.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 388 to queue - size 6 2020-02-11 14:05:31.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.470 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 381: Transaction COMPLETED 2020-02-11 14:05:31.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 61ms 2020-02-11 14:05:31.473 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 13: Init node thread finished 2020-02-11 14:05:31.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 381: Transaction completed 2020-02-11 14:05:31.474 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer - advancing to IDENTIFY_NODE 2020-02-11 14:05:31.475 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer: Initialisation starting 2020-02-11 14:05:31.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:381 DONE 2020-02-11 14:05:31.475 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_13_init complete 2020-02-11 14:05:31.476 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_15_init 2020-02-11 14:05:31.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.477 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_15_init complete 2020-02-11 14:05:31.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.477 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete 2020-02-11 14:05:31.478 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true 2020-02-11 14:05:31.479 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 05 BF 2020-02-11 14:05:31.480 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 05 BF 2020-02-11 14:05:31.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to ONLINE. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.482 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:cf541806' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller status changed to ONLINE. 2020-02-11 14:05:31.482 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to ONLINE. 2020-02-11 14:05:31.483 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Controller is ONLINE. Starting device initialisation. 2020-02-11 14:05:31.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller is ONLINE. Starting device initialisation. 2020-02-11 14:05:31.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is ONLINE. Starting device initialisation. 2020-02-11 14:05:31.485 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. 2020-02-11 14:05:31.486 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. 2020-02-11 14:05:31.486 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=271 2020-02-11 14:05:31.482 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller status changed to ONLINE. 2020-02-11 14:05:31.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. MAN=134 2020-02-11 14:05:31.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller is ONLINE. Starting device initialisation. 2020-02-11 14:05:31.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. MAN=134. SET. Was 134 2020-02-11 14:05:31.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@172330a 2020-02-11 14:05:31.489 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Updating node properties. 2020-02-11 14:05:31.482 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller status changed to ONLINE. 2020-02-11 14:05:31.490 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Properties synchronised 2020-02-11 14:05:31.490 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller is ONLINE. Starting device initialisation. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.492 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Updating node properties. MAN=351 2020-02-11 14:05:31.494 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Updating node properties. MAN=351. SET. Was 351 2020-02-11 14:05:31.495 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Properties synchronised ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.496 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.497 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:31.498 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising Thing Node... ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.499 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.499 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising cmd channel zwave:device:cf541806:node15:alarm_smoke for DecimalType 2020-02-11 14:05:31.500 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising state channel zwave:device:cf541806:node15:alarm_smoke for DecimalType 2020-02-11 14:05:31.501 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising cmd channel zwave:device:cf541806:node15:sensor_relhumidity for DecimalType 2020-02-11 14:05:31.506 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 382: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 381: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.502 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising state channel zwave:device:cf541806:node15:sensor_relhumidity for DecimalType 2020-02-11 14:05:31.504 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating node properties. 2020-02-11 14:05:31.504 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. 2020-02-11 14:05:31.517 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=271 2020-02-11 14:05:31.503 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Updating node properties. MAN=271. SET. Was 271 2020-02-11 14:05:31.518 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=271. SET. Was 271 2020-02-11 14:05:31.518 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Properties synchronised 2020-02-11 14:05:31.517 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating node properties. MAN=271 2020-02-11 14:05:31.520 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.521 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating node properties. MAN=271. SET. Was 271 2020-02-11 14:05:31.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Properties synchronised 2020-02-11 14:05:31.523 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=2, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.526 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.509 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.516 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1f31247 2020-02-11 14:05:31.526 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=3, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.519 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Properties synchronised 2020-02-11 14:05:31.528 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=Lifeline, profile1=0, profile2=1, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.514 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.530 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Update ASSOCIATION group_ZWaveAssociationGroup [index=2, name=Flood Control, profile1=113, profile2=5, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.531 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Update ASSOCIATION group_ZWaveAssociationGroup [index=3, name=Flood Alarm, profile1=113, profile2=5, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.532 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Update ASSOCIATION group_ZWaveAssociationGroup [index=4, name=Tamper Alarm, profile1=113, profile2=7, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 389 to queue - size 6 2020-02-11 14:05:31.515 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising cmd channel zwave:device:cf541806:node15:sensor_luminance for DecimalType 2020-02-11 14:05:31.532 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Update ASSOCIATION group_ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.533 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.534 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising state channel zwave:device:cf541806:node15:sensor_luminance for DecimalType 2020-02-11 14:05:31.534 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node... 2020-02-11 14:05:31.530 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.535 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising cmd channel zwave:device:cf541806:node15:sensor_temperature for QuantityType 2020-02-11 14:05:31.536 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising state channel zwave:device:cf541806:node15:sensor_temperature for QuantityType 2020-02-11 14:05:31.536 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation 2020-02-11 14:05:31.537 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE 2020-02-11 14:05:31.537 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising cmd channel zwave:device:cf541806:node15:alarm_co2 for DecimalType 2020-02-11 14:05:31.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.535 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:sensor_temperature for QuantityType 2020-02-11 14:05:31.538 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising state channel zwave:device:cf541806:node15:alarm_co2 for DecimalType ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.536 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:cf541806' has been updated. ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.539 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:31.540 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling initialised at 86400 seconds - start in 65750400 milliseconds. 2020-02-11 14:05:31.541 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Device initialisation complete. 2020-02-11 14:05:31.541 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab2/zwave/network_e5a7b0ac__node_1.xml 2020-02-11 14:05:31.541 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE. 2020-02-11 14:05:31.542 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation. 2020-02-11 14:05:31.540 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising Thing Node... 2020-02-11 14:05:31.544 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. 2020-02-11 14:05:31.544 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=Lifeline, profile1=0, profile2=1, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.545 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=881 2020-02-11 14:05:31.545 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Update ASSOCIATION group_ZWaveAssociationGroup [index=2, name=On/Off, profile1=32, profile2=1, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.546 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=881. SET. Was 881 2020-02-11 14:05:31.547 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.550 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.551 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising cmd channel zwave:device:cf541806:node13:scene_number for DecimalType 2020-02-11 14:05:31.541 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:31.547 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Update ASSOCIATION group_ZWaveAssociationGroup [index=4, name=Alarm, profile1=32, profile2=1, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.540 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:sensor_temperature for QuantityType 2020-02-11 14:05:31.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 382: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.555 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising state channel zwave:device:cf541806:node13:scene_number for DecimalType 2020-02-11 14:05:31.556 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding Controller (node_1) 2020-02-11 14:05:31.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.554 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:sensor_ultraviolet for DecimalType 2020-02-11 14:05:31.554 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising Thing Node... 2020-02-11 14:05:31.557 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising cmd channel zwave:device:cf541806:node13:alarm_general for OnOffType 2020-02-11 14:05:31.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.558 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising cmd channel zwave:device:cf541806:node10:sensor_temperature for QuantityType 2020-02-11 14:05:31.558 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising state channel zwave:device:cf541806:node10:sensor_temperature for QuantityType 2020-02-11 14:05:31.559 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 18 01 65 2020-02-11 14:05:31.560 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising cmd channel zwave:device:cf541806:node10:alarm_tamper for OnOffType 2020-02-11 14:05:31.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.558 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising state channel zwave:device:cf541806:node13:alarm_general for OnOffType 2020-02-11 14:05:31.562 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:sensor_ultraviolet for DecimalType 2020-02-11 14:05:31.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 382: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.563 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:sensor_luminance for DecimalType 2020-02-11 14:05:31.564 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising cmd channel zwave:device:cf541806:node13:battery-level for PercentType 2020-02-11 14:05:31.565 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:sensor_luminance for DecimalType 2020-02-11 14:05:31.561 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising state channel zwave:device:cf541806:node10:alarm_tamper for OnOffType 2020-02-11 14:05:31.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 382: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.566 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising cmd channel zwave:device:cf541806:node10:alarm_flood for OnOffType 2020-02-11 14:05:31.566 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:sensor_relhumidity for DecimalType 2020-02-11 14:05:31.566 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.566 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising state channel zwave:device:cf541806:node13:battery-level for PercentType 2020-02-11 14:05:31.567 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: ProtocolInfo 2020-02-11 14:05:31.568 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Listening = false 2020-02-11 14:05:31.567 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:sensor_relhumidity for DecimalType 2020-02-11 14:05:31.569 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Routing = true 2020-02-11 14:05:31.570 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Beaming = true 2020-02-11 14:05:31.570 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising state channel zwave:device:cf541806:node10:alarm_flood for OnOffType 2020-02-11 14:05:31.568 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:31.571 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising cmd channel zwave:device:cf541806:node10:battery-level for PercentType 2020-02-11 14:05:31.570 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Version = 4 2020-02-11 14:05:31.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising state channel zwave:device:cf541806:node10:battery-level for PercentType 2020-02-11 14:05:31.573 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling initialised at 86400 seconds - start in 35337600 milliseconds. 2020-02-11 14:05:31.574 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Device initialisation complete. 2020-02-11 14:05:31.570 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:alarm_motion for OnOffType 2020-02-11 14:05:31.574 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2020-02-11 14:05:31.574 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node... 2020-02-11 14:05:31.576 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising Thing Node... 2020-02-11 14:05:31.576 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling initialised at 86400 seconds - start in 1382400 milliseconds. 2020-02-11 14:05:31.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:switch_binary for OnOffType 2020-02-11 14:05:31.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Device initialisation complete. 2020-02-11 14:05:31.575 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:alarm_motion for OnOffType 2020-02-11 14:05:31.575 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: FLIRS = false 2020-02-11 14:05:31.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:cf541806:node12:scene_number for DecimalType 2020-02-11 14:05:31.579 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Security = false 2020-02-11 14:05:31.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:alarm_tamper for OnOffType 2020-02-11 14:05:31.579 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Max Baud = 40000 2020-02-11 14:05:31.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:cf541806:node12:scene_number for DecimalType 2020-02-11 14:05:31.580 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.580 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:alarm_tamper for OnOffType 2020-02-11 14:05:31.581 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Generic = GENERIC_TYPE_WALL_CONTROLLER 2020-02-11 14:05:31.581 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 5: Specific = SPECIFIC_TYPE_BASIC_WALL_CONTROLLER 2020-02-11 14:05:31.581 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:cf541806:node12:alarm_general for OnOffType 2020-02-11 14:05:31.581 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:cf541806:node2:battery-level for PercentType 2020-02-11 14:05:31.582 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.583 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.583 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:cf541806:node12:alarm_general for OnOffType 2020-02-11 14:05:31.583 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.584 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.585 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.585 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:cf541806:node12:battery-level for PercentType 2020-02-11 14:05:31.586 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.587 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.588 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 382: Transaction COMPLETED 2020-02-11 14:05:31.588 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:cf541806:node12:battery-level for PercentType 2020-02-11 14:05:31.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 80ms 2020-02-11 14:05:31.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 382: Transaction completed 2020-02-11 14:05:31.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:382 DONE 2020-02-11 14:05:31.590 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 1800 seconds - start in 698400 milliseconds. 2020-02-11 14:05:31.583 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:switch_binary for OnOffType 2020-02-11 14:05:31.591 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:cf541806:node2:battery-level for PercentType 2020-02-11 14:05:31.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Device initialisation complete. 2020-02-11 14:05:31.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:switch_binary for OnOffType 2020-02-11 14:05:31.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 86400 seconds - start in 72748800 milliseconds. 2020-02-11 14:05:31.593 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Device initialisation complete. 2020-02-11 14:05:31.594 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:switch_dimmer for OnOffType 2020-02-11 14:05:31.594 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:switch_dimmer for PercentType 2020-02-11 14:05:31.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.597 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 0A B0 2020-02-11 14:05:31.597 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 02 06 31 05 01 22 01 12 CD 00 38 2020-02-11 14:05:31.596 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:switch_dimmer for PercentType 2020-02-11 14:05:31.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 382: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.598 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 0A B0 2020-02-11 14:05:31.600 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:scene_number for DecimalType 2020-02-11 14:05:31.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@111d5b2 2020-02-11 14:05:31.601 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:scene_number for DecimalType 2020-02-11 14:05:31.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.602 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - advancing to REQUEST_NIF 2020-02-11 14:05:31.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:meter_current for DecimalType 2020-02-11 14:05:31.604 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 383: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@135434 2020-02-11 14:05:31.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 31 05 01 22 01 12 CD 00 2020-02-11 14:05:31.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Bump transaction 390 priority from Controller to Immediate 2020-02-11 14:05:31.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue 2020-02-11 14:05:31.608 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added 390 to queue - size 2 2020-02-11 14:05:31.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:meter_current for DecimalType 2020-02-11 14:05:31.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 31 05 01 22 01 12 CD 00 2020-02-11 14:05:31.612 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 07 01 7A 2020-02-11 14:05:31.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 383: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.613 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:meter_kwh for DecimalType 2020-02-11 14:05:31.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 07 01 2020-02-11 14:05:31.614 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:meter_kwh for DecimalType 2020-02-11 14:05:31.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:IDENTIFY_NODE) 2020-02-11 14:05:31.615 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 2020-02-11 14:05:31.616 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:31.615 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:meter_watts for DecimalType 2020-02-11 14:05:31.617 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT 2020-02-11 14:05:31.617 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:meter_watts for DecimalType 2020-02-11 14:05:31.618 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Type = Temperature(1), Scale = 0 2020-02-11 14:05:31.619 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:meter_voltage for DecimalType 2020-02-11 14:05:31.620 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Value = 27.4 2020-02-11 14:05:31.621 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:meter_voltage for DecimalType 2020-02-11 14:05:31.621 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2020-02-11 14:05:31.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:color_color for OnOffType 2020-02-11 14:05:31.623 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=27.4 2020-02-11 14:05:31.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:color_color for PercentType 2020-02-11 14:05:31.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:sensor_temperature to 27.4 °C [QuantityType] 2020-02-11 14:05:31.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:color_color for PercentType 2020-02-11 14:05:31.627 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:color_color for HSBType 2020-02-11 14:05:31.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:31.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@742f23. 2020-02-11 14:05:31.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:31.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:31.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:color_color for HSBType 2020-02-11 14:05:31.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:color_temperature for OnOffType 2020-02-11 14:05:31.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 383: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:color_temperature for PercentType 2020-02-11 14:05:31.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 07 01 2020-02-11 14:05:31.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:color_temperature for PercentType 2020-02-11 14:05:31.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 383: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.637 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:alarm_power for OnOffType 2020-02-11 14:05:31.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 383: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.639 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 07 01 2020-02-11 14:05:31.638 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:alarm_power for OnOffType 2020-02-11 14:05:31.640 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: ProtocolInfo 2020-02-11 14:05:31.640 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:alarm_system for OnOffType 2020-02-11 14:05:31.641 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Listening = false 2020-02-11 14:05:31.641 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:alarm_system for OnOffType 2020-02-11 14:05:31.642 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Routing = true 2020-02-11 14:05:31.642 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Beaming = true 2020-02-11 14:05:31.643 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising cmd channel zwave:device:cf541806:node3:time_offset for DecimalType 2020-02-11 14:05:31.644 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Version = 4 2020-02-11 14:05:31.644 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising state channel zwave:device:cf541806:node3:time_offset for DecimalType ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.644 [vent.ItemStateChangedEvent] - item_1581420568563 changed from 27.5 °C to 27.4 °C ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.645 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: FLIRS = false 2020-02-11 14:05:31.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling initialised at 1800 seconds - start in 1134000 milliseconds. 2020-02-11 14:05:31.645 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Security = false 2020-02-11 14:05:31.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete. 2020-02-11 14:05:31.646 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Max Baud = 40000 2020-02-11 14:05:31.647 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.648 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Generic = GENERIC_TYPE_SENSOR_NOTIFICATION 2020-02-11 14:05:31.649 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 10: Specific = SPECIFIC_TYPE_NOTIFICATION_SENSOR 2020-02-11 14:05:31.650 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.650 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.651 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.652 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.653 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.654 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.655 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.655 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 383: Transaction COMPLETED 2020-02-11 14:05:31.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 52ms 2020-02-11 14:05:31.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 383: Transaction completed 2020-02-11 14:05:31.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:383 DONE 2020-02-11 14:05:31.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 383: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.661 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@19f36d4 2020-02-11 14:05:31.661 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 0F B5 2020-02-11 14:05:31.662 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.662 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 0F B5 2020-02-11 14:05:31.663 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.663 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer - advancing to REQUEST_NIF 2020-02-11 14:05:31.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 384: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.663 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@9db2c3 2020-02-11 14:05:31.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Bump transaction 391 priority from Controller to Immediate 2020-02-11 14:05:31.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue 2020-02-11 14:05:31.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Added 391 to queue - size 3 ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.669 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node10' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.670 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.673 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 21 01 DC 2020-02-11 14:05:31.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 384: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 384: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 384: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.688 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.689 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: ProtocolInfo 2020-02-11 14:05:31.689 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Listening = true 2020-02-11 14:05:31.690 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Routing = true 2020-02-11 14:05:31.690 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Beaming = true 2020-02-11 14:05:31.691 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Version = 4 2020-02-11 14:05:31.692 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: FLIRS = false 2020-02-11 14:05:31.693 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Security = false 2020-02-11 14:05:31.693 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Max Baud = 40000 2020-02-11 14:05:31.694 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.695 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Generic = GENERIC_TYPE_SENSOR_MULTILEVEL 2020-02-11 14:05:31.695 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 15: Specific = SPECIFIC_TYPE_ROUTING_SENSOR_MULTILEVEL 2020-02-11 14:05:31.697 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.698 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.698 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.699 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.700 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.701 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 15: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.701 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.702 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 384: Transaction COMPLETED 2020-02-11 14:05:31.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 40ms 2020-02-11 14:05:31.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 384: Transaction completed 2020-02-11 14:05:31.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:384 DONE 2020-02-11 14:05:31.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 384: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.706 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@10b744d 2020-02-11 14:05:31.707 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8 2020-02-11 14:05:31.707 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.707 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node advancer - advancing to PING 2020-02-11 14:05:31.707 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8 2020-02-11 14:05:31.708 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.709 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.709 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 386: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.711 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 15: Creating new message for command NO_OPERATION_PING 2020-02-11 14:05:31.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.712 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 21 01 DC 2020-02-11 14:05:31.712 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: ZWaveCommandClassTransactionPayload - send to node 2020-02-11 14:05:31.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 386: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.713 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported 2020-02-11 14:05:31.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.714 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.715 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node15' changed from ONLINE to ONLINE: Node initialising: PING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@134eef4 2020-02-11 14:05:31.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue 2020-02-11 14:05:31.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 386: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Added 392 to queue - size 4 2020-02-11 14:05:31.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 386: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.720 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 21 01 2020-02-11 14:05:31.721 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: ProtocolInfo 2020-02-11 14:05:31.721 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Listening = true 2020-02-11 14:05:31.722 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Routing = true 2020-02-11 14:05:31.723 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Beaming = true 2020-02-11 14:05:31.724 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Version = 4 2020-02-11 14:05:31.724 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: FLIRS = false 2020-02-11 14:05:31.725 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false 2020-02-11 14:05:31.725 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Max Baud = 40000 2020-02-11 14:05:31.726 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.727 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Generic = GENERIC_TYPE_SENSOR_MULTILEVEL 2020-02-11 14:05:31.728 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Specific = SPECIFIC_TYPE_ROUTING_SENSOR_MULTILEVEL 2020-02-11 14:05:31.728 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.729 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.730 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.730 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.731 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.732 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.733 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.734 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 386: Transaction COMPLETED 2020-02-11 14:05:31.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 25ms 2020-02-11 14:05:31.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 386: Transaction completed 2020-02-11 14:05:31.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:386 DONE 2020-02-11 14:05:31.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 386: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.737 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@130f6f7 2020-02-11 14:05:31.738 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.738 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to PING 2020-02-11 14:05:31.739 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.740 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 2: Creating new message for command NO_OPERATION_PING 2020-02-11 14:05:31.740 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: ZWaveCommandClassTransactionPayload - send to node 2020-02-11 14:05:31.741 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:31.742 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured 2020-02-11 14:05:31.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@3279f5 2020-02-11 14:05:31.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.744 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node2' changed from ONLINE to ONLINE: Node initialising: PING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.744 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 03 B9 2020-02-11 14:05:31.745 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 03 B9 2020-02-11 14:05:31.747 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 387: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.748 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.750 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 9C 01 04 10 01 ED 2020-02-11 14:05:31.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 387: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 10 01 2020-02-11 14:05:31.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue 2020-02-11 14:05:31.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 393 to queue - size 5 2020-02-11 14:05:31.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 10 01 2020-02-11 14:05:31.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 387: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 387: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.756 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 9C 01 04 10 01 2020-02-11 14:05:31.757 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: ProtocolInfo 2020-02-11 14:05:31.758 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Listening = true 2020-02-11 14:05:31.759 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Routing = true 2020-02-11 14:05:31.760 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Beaming = true 2020-02-11 14:05:31.761 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Version = 4 2020-02-11 14:05:31.762 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: FLIRS = false 2020-02-11 14:05:31.763 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Security = false 2020-02-11 14:05:31.764 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Max Baud = 40000 2020-02-11 14:05:31.764 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.765 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Generic = GENERIC_TYPE_SWITCH_BINARY 2020-02-11 14:05:31.766 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 3: Specific = SPECIFIC_TYPE_POWER_SWITCH_BINARY 2020-02-11 14:05:31.767 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.768 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.769 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.769 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.770 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.771 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.772 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 387: Transaction COMPLETED 2020-02-11 14:05:31.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 25ms 2020-02-11 14:05:31.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 387: Transaction completed 2020-02-11 14:05:31.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:387 DONE 2020-02-11 14:05:31.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 387: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.777 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d0a377 2020-02-11 14:05:31.778 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.778 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 0C B6 2020-02-11 14:05:31.778 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to PING 2020-02-11 14:05:31.779 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.780 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 0C B6 2020-02-11 14:05:31.781 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.782 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 388: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.784 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 18 01 65 2020-02-11 14:05:31.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 388: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.787 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 3: Creating new message for command NO_OPERATION_PING ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.787 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node3' changed from ONLINE to ONLINE: Node initialising: PING ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.788 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node 2020-02-11 14:05:31.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 388: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.788 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY doesn't encrypt PING 2020-02-11 14:05:31.789 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured 2020-02-11 14:05:31.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1d22849 2020-02-11 14:05:31.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 388: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue 2020-02-11 14:05:31.792 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 394 to queue - size 6 2020-02-11 14:05:31.793 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: ProtocolInfo 2020-02-11 14:05:31.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.795 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Listening = false 2020-02-11 14:05:31.795 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Routing = true 2020-02-11 14:05:31.796 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Beaming = true 2020-02-11 14:05:31.797 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Version = 4 2020-02-11 14:05:31.798 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: FLIRS = false 2020-02-11 14:05:31.799 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Security = false 2020-02-11 14:05:31.799 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Max Baud = 40000 2020-02-11 14:05:31.800 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.801 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Generic = GENERIC_TYPE_WALL_CONTROLLER 2020-02-11 14:05:31.802 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 12: Specific = SPECIFIC_TYPE_BASIC_WALL_CONTROLLER 2020-02-11 14:05:31.802 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.804 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.804 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.805 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.806 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.807 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.808 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.809 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 388: Transaction COMPLETED 2020-02-11 14:05:31.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 27ms 2020-02-11 14:05:31.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 388: Transaction completed 2020-02-11 14:05:31.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:388 DONE 2020-02-11 14:05:31.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 388: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.813 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@9e249c 2020-02-11 14:05:31.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.814 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.815 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - advancing to REQUEST_NIF 2020-02-11 14:05:31.815 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 0D B7 2020-02-11 14:05:31.816 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.816 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 0D B7 2020-02-11 14:05:31.817 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19cb5ab 2020-02-11 14:05:31.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 389: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 395 priority from Controller to Immediate 2020-02-11 14:05:31.820 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.821 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node12' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.821 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 53 9C 01 04 18 01 65 2020-02-11 14:05:31.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 389: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2020-02-11 14:05:31.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 395 to queue - size 7 2020-02-11 14:05:31.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 389: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 389: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0 2020-02-11 14:05:31.829 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=53 9C 01 04 18 01 2020-02-11 14:05:31.830 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: ProtocolInfo 2020-02-11 14:05:31.831 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Listening = false 2020-02-11 14:05:31.832 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Routing = true 2020-02-11 14:05:31.833 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Beaming = true 2020-02-11 14:05:31.834 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Version = 4 2020-02-11 14:05:31.834 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: FLIRS = false 2020-02-11 14:05:31.835 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Security = false 2020-02-11 14:05:31.836 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Max Baud = 40000 2020-02-11 14:05:31.837 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Basic = BASIC_TYPE_ROUTING_SLAVE 2020-02-11 14:05:31.837 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Generic = GENERIC_TYPE_WALL_CONTROLLER 2020-02-11 14:05:31.838 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 13: Specific = SPECIFIC_TYPE_BASIC_WALL_CONTROLLER 2020-02-11 14:05:31.839 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Creating new instance of command class COMMAND_CLASS_NO_OPERATION 2020-02-11 14:05:31.840 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created 2020-02-11 14:05:31.840 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Version = 1, version set. Enabling extra functionality. 2020-02-11 14:05:31.841 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes. 2020-02-11 14:05:31.842 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Creating new instance of command class COMMAND_CLASS_BASIC 2020-02-11 14:05:31.843 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 13: Command class COMMAND_CLASS_BASIC, endpoint 0 created 2020-02-11 14:05:31.844 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes. 2020-02-11 14:05:31.845 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 389: Transaction COMPLETED 2020-02-11 14:05:31.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 28ms 2020-02-11 14:05:31.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 389: Transaction completed 2020-02-11 14:05:31.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:389 DONE 2020-02-11 14:05:31.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 389: Transaction event listener: DONE: DONE -> 2020-02-11 14:05:31.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:31.850 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@18a587a 2020-02-11 14:05:31.850 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init transaction completed with response COMPLETE 2020-02-11 14:05:31.850 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 0F 01 00 25 57 98 2020-02-11 14:05:31.851 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer - advancing to REQUEST_NIF 2020-02-11 14:05:31.851 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 15: Sending REQUEST Message = 01 08 00 13 0F 01 00 25 57 98 2020-02-11 14:05:31.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveInitializationStateEvent 2020-02-11 14:05:31.852 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:31.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@88ccaf 2020-02-11 14:05:31.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:31.854 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:31.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Bump transaction 396 priority from Controller to Immediate 2020-02-11 14:05:31.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue 2020-02-11 14:05:31.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 396 to queue - size 7 2020-02-11 14:05:31.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:31.857 [hingStatusInfoChangedEvent] - 'zwave:device:cf541806:node13' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:31.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:31.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:31.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:31.863 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-02-11 14:05:31.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:31.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:31.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:31.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:31.869 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:31.870 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: sentData successfully placed on stack. 2020-02-11 14:05:31.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 392: Advanced to WAIT_REQUEST 2020-02-11 14:05:31.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 392: Transaction not completed 2020-02-11 14:05:31.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:31.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:32.104 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 05 31 05 05 01 27 CD 00 2B 2020-02-11 14:05:32.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 31 05 05 01 27 CD 00 2020-02-11 14:05:32.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 31 05 05 01 27 CD 00 2020-02-11 14:05:32.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:32.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:PING) 2020-02-11 14:05:32.108 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 2020-02-11 14:05:32.109 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:32.110 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT 2020-02-11 14:05:32.111 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Type = RelativeHumidity(5), Scale = 0 2020-02-11 14:05:32.112 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Value = 39 2020-02-11 14:05:32.113 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2020-02-11 14:05:32.113 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=39 2020-02-11 14:05:32.115 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 2: Sensor conversion not performed for RELATIVE_HUMIDITY. 2020-02-11 14:05:32.116 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:sensor_relhumidity to 39 [DecimalType] 2020-02-11 14:05:32.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:32.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4631cb. 2020-02-11 14:05:32.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:32.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:32.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:32.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:33.181 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 02 03 80 03 64 CD 00 DB 2020-02-11 14:05:33.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 CD 00 2020-02-11 14:05:33.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 CD 00 2020-02-11 14:05:33.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:33.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:PING) 2020-02-11 14:05:33.195 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0 2020-02-11 14:05:33.197 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:33.198 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT 2020-02-11 14:05:33.200 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 2: Battery report value = 100 2020-02-11 14:05:33.201 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2020-02-11 14:05:33.203 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=100 2020-02-11 14:05:33.205 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:battery-level to 100 [DecimalType] 2020-02-11 14:05:33.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:33.210 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@195f4cc. 2020-02-11 14:05:33.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.215 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:33.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:33.334 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 02 03 80 03 64 CF 00 D9 2020-02-11 14:05:33.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 CF 00 2020-02-11 14:05:33.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 80 03 64 CF 00 2020-02-11 14:05:33.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:33.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:PING) 2020-02-11 14:05:33.343 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0 2020-02-11 14:05:33.344 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:33.346 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT 2020-02-11 14:05:33.348 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 2: Battery report value = 100 2020-02-11 14:05:33.349 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2020-02-11 14:05:33.351 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=100 2020-02-11 14:05:33.353 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:battery-level to 100 [DecimalType] 2020-02-11 14:05:33.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:33.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f9788d. 2020-02-11 14:05:33.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:33.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:33.449 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 02 06 31 05 03 0A 02 8D CF 00 8C 2020-02-11 14:05:33.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 31 05 03 0A 02 8D CF 00 2020-02-11 14:05:33.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 06 31 05 03 0A 02 8D CF 00 2020-02-11 14:05:33.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:33.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:PING) 2020-02-11 14:05:33.457 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 2020-02-11 14:05:33.459 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:33.460 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT 2020-02-11 14:05:33.462 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Type = Luminance(3), Scale = 1 2020-02-11 14:05:33.464 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Value = 653 2020-02-11 14:05:33.465 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2020-02-11 14:05:33.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=653 2020-02-11 14:05:33.469 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:sensor_luminance to 653 % [QuantityType] 2020-02-11 14:05:33.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:33.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1415e86. 2020-02-11 14:05:33.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.479 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty ==> /var/log/openhab2/events.log <== 2020-02-11 14:05:33.480 [vent.ItemStateChangedEvent] - item_1581420523573 changed from 661 to 653 ==> /var/log/openhab2/openhab.log <== 2020-02-11 14:05:33.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:33.492 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'luminance': java.lang.String cannot be cast to java.lang.Number 2020-02-11 14:05:33.558 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 05 31 05 1B 01 00 CF 00 10 2020-02-11 14:05:33.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 31 05 1B 01 00 CF 00 2020-02-11 14:05:33.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 31 05 1B 01 00 CF 00 2020-02-11 14:05:33.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:33.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:PING) 2020-02-11 14:05:33.566 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0 2020-02-11 14:05:33.567 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-02-11 14:05:33.568 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT 2020-02-11 14:05:33.571 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Type = Ultraviolet(27), Scale = 0 2020-02-11 14:05:33.573 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 2: Sensor Value = 0E+1 2020-02-11 14:05:33.574 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2020-02-11 14:05:33.576 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0E+1 2020-02-11 14:05:33.577 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 2: Sensor conversion not performed for ULTRAVIOLET. 2020-02-11 14:05:33.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:cf541806:node2:sensor_ultraviolet to 0 [DecimalType] 2020-02-11 14:05:33.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2020-02-11 14:05:33.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@8d4c91. 2020-02-11 14:05:33.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2020-02-11 14:05:33.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:33.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:36.873 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 15: TID 392: Timeout at state WAIT_REQUEST. 3 retries remaining. 2020-02-11 14:05:36.874 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-02-11 14:05:36.875 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction ABORTED 2020-02-11 14:05:36.876 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-02-11 14:05:36.877 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-02-11 14:05:36.879 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:36.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:36.882 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:36.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:36.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:36.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:36.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:36.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:36.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:38.511 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 57 01 02 9A 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 46 2020-02-11 14:05:38.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=87, payload=57 01 02 9A 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:38.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=87, payload=57 01 02 9A 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:38.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:38.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:38.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 87 2020-02-11 14:05:38.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 392: (Callback 87) 2020-02-11 14:05:38.526 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-02-11 14:05:38.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 392: callback 87 2020-02-11 14:05:38.528 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=87, payload=57 01 02 9A 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:38.529 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: SendData Request. CallBack ID = 87, Status = Transmission complete, no ACK received(1) 2020-02-11 14:05:38.530 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction CANCELLED 2020-02-11 14:05:38.532 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-02-11 14:05:38.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: CANCEL while sending message. Requeueing - 2 attempts left! 2020-02-11 14:05:38.534 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction RESET with 2 retries remaining. 2020-02-11 14:05:38.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue 2020-02-11 14:05:38.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Added 392 to queue - size 8 2020-02-11 14:05:38.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:38.539 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 0F 01 00 25 58 97 2020-02-11 14:05:38.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 15: Sending REQUEST Message = 01 08 00 13 0F 01 00 25 58 97 2020-02-11 14:05:38.541 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:38.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:38.543 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:38.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 392: Transaction not completed 2020-02-11 14:05:38.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:38.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:38.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:38.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:38.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:38.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:38.551 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:38.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:38.553 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-02-11 14:05:38.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:38.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:38.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:38.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:38.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:38.561 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:38.563 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: sentData successfully placed on stack. 2020-02-11 14:05:38.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 392: Advanced to WAIT_REQUEST 2020-02-11 14:05:38.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 392: Transaction not completed 2020-02-11 14:05:38.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:38.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:43.565 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 15: TID 392: Timeout at state WAIT_REQUEST. 2 retries remaining. 2020-02-11 14:05:43.566 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-02-11 14:05:43.572 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction ABORTED 2020-02-11 14:05:43.574 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-02-11 14:05:43.575 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-02-11 14:05:43.577 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:43.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:43.578 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:43.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:43.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:43.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:43.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:43.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:43.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:45.409 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 58 01 02 AE 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 7D 2020-02-11 14:05:45.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=88, payload=58 01 02 AE 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:45.415 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=88, payload=58 01 02 AE 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:45.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:45.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:45.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 392: [ABORTED] priority=Poll, requiresResponse=true, callback: 88 2020-02-11 14:05:45.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 392: (Callback 88) 2020-02-11 14:05:45.421 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-02-11 14:05:45.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 392: callback 88 2020-02-11 14:05:45.423 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=88, payload=58 01 02 AE 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 0B 03 0F 2020-02-11 14:05:45.424 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: SendData Request. CallBack ID = 88, Status = Transmission complete, no ACK received(1) 2020-02-11 14:05:45.426 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction CANCELLED 2020-02-11 14:05:45.427 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-02-11 14:05:45.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: CANCEL while sending message. Requeueing - 1 attempts left! 2020-02-11 14:05:45.429 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 392: Transaction RESET with 1 retries remaining. 2020-02-11 14:05:45.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue 2020-02-11 14:05:45.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Added 392 to queue - size 8 2020-02-11 14:05:45.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-02-11 14:05:45.433 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 0F 01 00 25 59 96 2020-02-11 14:05:45.435 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 15: Sending REQUEST Message = 01 08 00 13 0F 01 00 25 59 96 2020-02-11 14:05:45.436 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-02-11 14:05:45.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 89 2020-02-11 14:05:45.437 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-02-11 14:05:45.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 392: Transaction not completed 2020-02-11 14:05:45.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:45.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:45.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:45.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-02-11 14:05:45.444 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 89 2020-02-11 14:05:45.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-02-11 14:05:45.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:45.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-02-11 14:05:45.448 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-02-11 14:05:45.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:45.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:45.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 89 2020-02-11 14:05:45.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-02-11 14:05:45.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 392: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 89 2020-02-11 14:05:45.458 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-02-11 14:05:45.459 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: sentData successfully placed on stack. 2020-02-11 14:05:45.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 392: Advanced to WAIT_REQUEST 2020-02-11 14:05:45.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 392: Transaction not completed 2020-02-11 14:05:45.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-02-11 14:05:45.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.