2020-04-24 18:47:33.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:32.995 [DEBUG] [age.AssignSucReturnRouteMessageClass] - NODE 13: AssignSucReturnRoute operation started. 2020-04-24 18:47:33.004 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.007 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:47:33.008 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1 2020-04-24 18:47:33.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34164: Advanced to WAIT_REQUEST 2020-04-24 18:47:33.012 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:47:33.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 34164: Transaction not completed 2020-04-24 18:47:33.016 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-04-24 18:47:33.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (9): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34164: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 118 2020-04-24 18:47:33.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 9<>119 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 64 00 00 00 00 00 78 00 00 00 00 2020-04-24 18:47:33.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:47:33.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue 2020-04-24 18:47:33.036 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Command received zwave:device:894dd1c6:node22:switch_dimmer --> 0 [PercentType] 2020-04-24 18:47:33.039 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 22: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:47:33.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 34180 to queue - size 16 2020-04-24 18:47:33.043 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: SECURITY not supported 2020-04-24 18:47:33.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:33.044 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:894dd1c6:node11:switch_binary1 --> OFF [OnOffType] 2020-04-24 18:47:33.046 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:47:33.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:47:33.049 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Encapsulating message, instance / endpoint 1 2020-04-24 18:47:33.054 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 11: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:47:33.056 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: SECURITY not supported 2020-04-24 18:47:33.059 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:894dd1c6:node4:switch_dimmer --> 0 [PercentType] 2020-04-24 18:47:33.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:47:33.062 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:47:33.064 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported 2020-04-24 18:47:33.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started... 2020-04-24 18:47:33.067 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:47:33.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34164: Resetting transaction 2020-04-24 18:47:33.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:34164 WAIT_REQUEST 2020-04-24 18:47:33.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue 2020-04-24 18:47:33.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 34183 to queue - size 17 2020-04-24 18:47:33.068 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff true. 2020-04-24 18:47:33.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34164: Transaction event listener: DONE: WAIT_REQUEST -> 2020-04-24 18:47:33.086 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Completing UNINTIALIZED transaction 34164!!! How?!? 2020-04-24 18:47:33.085 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.089 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@166cc0e 2020-04-24 18:47:33.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue 2020-04-24 18:47:33.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Added 34182 to queue - size 18 2020-04-24 18:47:33.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff true. 2020-04-24 18:47:33.098 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Command received zwave:device:894dd1c6:node20:switch_binary1 --> OFF [OnOffType] 2020-04-24 18:47:33.102 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.103 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 20: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:47:33.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: Adding to device queue 2020-04-24 18:47:33.105 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Encapsulating message, instance / endpoint 1 2020-04-24 18:47:33.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: Added 34181 to queue - size 19 2020-04-24 18:47:33.106 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 20: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:47:33.108 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY not supported 2020-04-24 18:47:33.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff true. 2020-04-24 18:47:33.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue 2020-04-24 18:47:33.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 34164 to queue - size 20 2020-04-24 18:47:33.110 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (9): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (8): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.123 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:47:33.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Adding to device queue 2020-04-24 18:47:33.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (7): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (6): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Added 34184 to queue - size 21 2020-04-24 18:47:33.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (5): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (4): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (3): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (2): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload= 2020-04-24 18:47:33.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=AssignSucReturnRoute[81], type=Request[0], dest=4, callback=109, payload=6D 04 2020-04-24 18:47:33.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0 2020-04-24 18:47:33.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null 2020-04-24 18:47:33.162 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AssignSucReturnRoute[81], type=Request[0], dest=4, callback=109, payload=6D 04 2020-04-24 18:47:33.163 [DEBUG] [age.AssignSucReturnRouteMessageClass] - NODE {}: transaction not correlated for AssignSucReturnRouteMessageClass 2020-04-24 18:47:33.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 64 00 00 00 00 00 78 00 00 00 00 2020-04-24 18:47:33.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2020-04-24 18:47:33.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE) 2020-04-24 18:47:33.175 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false 2020-04-24 18:47:33.178 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0 2020-04-24 18:47:33.179 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY NOT required on COMMAND_CLASS_METER 2020-04-24 18:47:33.181 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT 2020-04-24 18:47:33.183 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=kWh(0), Value=0E+1 2020-04-24 18:47:33.186 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent 2020-04-24 18:47:33.186 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:894dd1c6:node6:switch_dimmer --> 0 [PercentType] 2020-04-24 18:47:33.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1 2020-04-24 18:47:33.188 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:47:33.190 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:894dd1c6:node3:meter_kwh to 0 [DecimalType] 2020-04-24 18:47:33.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported 2020-04-24 18:47:33.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:47:33.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue 2020-04-24 18:47:33.195 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:894dd1c6:node8:switch_dimmer --> 0 [PercentType] 2020-04-24 18:47:33.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added 34185 to queue - size 22 2020-04-24 18:47:33.198 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 8: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:47:33.200 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2020-04-24 18:47:33.202 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:47:33.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue 2020-04-24 18:47:33.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Added 34186 to queue - size 23 2020-04-24 18:47:33.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1. 2020-04-24 18:47:33.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@9cbeb2. 2020-04-24 18:47:33.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:894dd1c6:node9:switch_binary --> OFF [OnOffType] 2020-04-24 18:47:33.225 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 9: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:47:33.227 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY not supported 2020-04-24 18:47:33.230 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 2020-04-24 18:47:33.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2020-04-24 18:47:33.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2020-04-24 18:47:33.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Adding to device queue 2020-04-24 18:47:33.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Added 34187 to queue - size 24 2020-04-24 18:47:33.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.246 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:47:33.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true. 2020-04-24 18:47:33.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:33.319 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1B 03 26 01 00 25 77 8B 2020-04-24 18:47:33.322 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 27: Sending REQUEST Message = 01 0A 00 13 1B 03 26 01 00 25 77 8B 2020-04-24 18:47:33.323 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:33.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34166: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.327 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:33.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:33.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.332 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23624 to 23625 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34166: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:33.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.336 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:33.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.341 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67160 to 67161 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34166: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34166: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.352 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.353 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 27: sentData successfully placed on stack. 2020-04-24 18:47:33.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34166: Advanced to WAIT_REQUEST 2020-04-24 18:47:33.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: TID 34166: Transaction not completed 2020-04-24 18:47:33.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:33.414 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 77 00 00 09 95 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.415 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67161 to 67162 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=119, payload=77 00 00 09 2020-04-24 18:47:33.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=119, payload=77 00 00 09 2020-04-24 18:47:33.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34166: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34166: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 119 2020-04-24 18:47:33.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34166: (Callback 119) 2020-04-24 18:47:33.429 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:33.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34166: callback 119 2020-04-24 18:47:33.433 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=119, payload=77 00 00 09 2020-04-24 18:47:33.434 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 27: SendData Request. CallBack ID = 119, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:33.436 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34166: Transaction COMPLETED 2020-04-24 18:47:33.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: Response processed after 112ms 2020-04-24 18:47:33.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: TID 34166: Transaction completed 2020-04-24 18:47:33.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: notifyTransactionResponse TID:34166 DONE 2020-04-24 18:47:33.442 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:33.444 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:33.448 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1C 03 26 01 00 25 78 83 2020-04-24 18:47:33.450 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 28: Sending REQUEST Message = 01 0A 00 13 1C 03 26 01 00 25 78 83 2020-04-24 18:47:33.452 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:33.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34167: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.455 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:33.458 [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-04-24 18:47:33.458 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23625 to 23626 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:33.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34167: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:33.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:33.465 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:33.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.470 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67162 to 67163 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34167: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34167: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.477 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.478 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 28: sentData successfully placed on stack. 2020-04-24 18:47:33.479 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34167: Advanced to WAIT_REQUEST 2020-04-24 18:47:33.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: TID 34167: Transaction not completed 2020-04-24 18:47:33.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:33.543 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 78 00 00 08 9B 2020-04-24 18:47:33.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=120, payload=78 00 00 08 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.546 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67163 to 67164 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=120, payload=78 00 00 08 2020-04-24 18:47:33.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34167: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34167: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 120 2020-04-24 18:47:33.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34167: (Callback 120) 2020-04-24 18:47:33.554 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:33.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34167: callback 120 2020-04-24 18:47:33.557 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=120, payload=78 00 00 08 2020-04-24 18:47:33.558 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 28: SendData Request. CallBack ID = 120, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:33.559 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34167: Transaction COMPLETED 2020-04-24 18:47:33.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Response processed after 107ms 2020-04-24 18:47:33.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: TID 34167: Transaction completed 2020-04-24 18:47:33.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: notifyTransactionResponse TID:34167 DONE 2020-04-24 18:47:33.564 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:33.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:33.568 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 13 03 26 01 00 25 79 8D 2020-04-24 18:47:33.570 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 19: Sending REQUEST Message = 01 0A 00 13 13 03 26 01 00 25 79 8D 2020-04-24 18:47:33.571 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:33.572 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34168: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.573 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:33.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:33.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.578 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23626 to 23627 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34168: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:33.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.583 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67164 to 67165 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:33.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34168: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34168: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.594 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:33.595 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: sentData successfully placed on stack. 2020-04-24 18:47:33.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34168: Advanced to WAIT_REQUEST 2020-04-24 18:47:33.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: TID 34168: Transaction not completed 2020-04-24 18:47:33.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:33.662 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 79 00 00 08 9A ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.664 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67165 to 67166 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=121, payload=79 00 00 08 2020-04-24 18:47:33.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=121, payload=79 00 00 08 2020-04-24 18:47:33.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34168: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:33.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34168: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 121 2020-04-24 18:47:33.670 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34168: (Callback 121) 2020-04-24 18:47:33.672 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:33.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34168: callback 121 2020-04-24 18:47:33.674 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=121, payload=79 00 00 08 2020-04-24 18:47:33.676 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 19: SendData Request. CallBack ID = 121, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:33.677 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34168: Transaction COMPLETED 2020-04-24 18:47:33.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Response processed after 106ms 2020-04-24 18:47:33.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: TID 34168: Transaction completed 2020-04-24 18:47:33.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:34168 DONE 2020-04-24 18:47:33.682 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:33.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:33.686 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 12 03 26 01 00 25 7A 8F 2020-04-24 18:47:33.687 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 00 25 7A 8F 2020-04-24 18:47:33.689 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:33.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34169: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:33.691 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:33.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:33.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:33.695 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23627 to 23628 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:33.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34169: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:33.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:33.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:33.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:34.319 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling... 2020-04-24 18:47:34.321 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling deferred until initialisation complete 2020-04-24 18:47:34.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling... 2020-04-24 18:47:34.338 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling deferred until initialisation complete 2020-04-24 18:47:34.348 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling... 2020-04-24 18:47:34.350 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling deferred until initialisation complete 2020-04-24 18:47:34.373 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling... 2020-04-24 18:47:34.374 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete 2020-04-24 18:47:34.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling... 2020-04-24 18:47:34.381 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling deferred until initialisation complete 2020-04-24 18:47:34.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling... 2020-04-24 18:47:34.390 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling deferred until initialisation complete 2020-04-24 18:47:34.393 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling... 2020-04-24 18:47:34.395 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling deferred until initialisation complete 2020-04-24 18:47:34.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling... 2020-04-24 18:47:34.420 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling deferred until initialisation complete 2020-04-24 18:47:34.435 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling... 2020-04-24 18:47:34.438 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling deferred until initialisation complete 2020-04-24 18:47:34.440 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling... 2020-04-24 18:47:34.441 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling deferred until initialisation complete 2020-04-24 18:47:34.461 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling... 2020-04-24 18:47:34.465 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling deferred until initialisation complete 2020-04-24 18:47:34.472 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Polling... 2020-04-24 18:47:34.474 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Polling deferred until initialisation complete 2020-04-24 18:47:34.504 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling... 2020-04-24 18:47:34.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling deferred until initialisation complete 2020-04-24 18:47:34.568 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling... 2020-04-24 18:47:34.571 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling deferred until initialisation complete 2020-04-24 18:47:34.586 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling... 2020-04-24 18:47:34.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling deferred until initialisation complete 2020-04-24 18:47:34.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling... 2020-04-24 18:47:34.604 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling deferred until initialisation complete 2020-04-24 18:47:34.610 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling... 2020-04-24 18:47:34.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling deferred until initialisation complete 2020-04-24 18:47:34.639 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling... 2020-04-24 18:47:34.641 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling deferred until initialisation complete 2020-04-24 18:47:34.710 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling... 2020-04-24 18:47:34.710 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling... 2020-04-24 18:47:34.712 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling deferred until initialisation complete 2020-04-24 18:47:34.714 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling deferred until initialisation complete 2020-04-24 18:47:34.746 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling... 2020-04-24 18:47:34.749 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling deferred until initialisation complete 2020-04-24 18:47:34.961 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:34.965 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67166 to 67167 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:34.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:34.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:34.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34169: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:34.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:34.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34169: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:34.980 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:34.983 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: sentData successfully placed on stack. 2020-04-24 18:47:34.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34169: Advanced to WAIT_REQUEST 2020-04-24 18:47:34.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 34169: Transaction not completed 2020-04-24 18:47:34.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:34.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:35.351 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7A 00 00 A5 34 2020-04-24 18:47:35.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=122, payload=7A 00 00 A5 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:35.356 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67167 to 67168 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=122, payload=7A 00 00 A5 2020-04-24 18:47:35.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34169: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:35.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:35.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34169: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 122 2020-04-24 18:47:35.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34169: (Callback 122) 2020-04-24 18:47:35.370 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:35.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34169: callback 122 2020-04-24 18:47:35.375 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=122, payload=7A 00 00 A5 2020-04-24 18:47:35.377 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 122, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:35.379 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34169: Transaction COMPLETED 2020-04-24 18:47:35.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Response processed after 1691ms 2020-04-24 18:47:35.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 34169: Transaction completed 2020-04-24 18:47:35.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:34169 DONE 2020-04-24 18:47:35.388 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:35.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:35.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:35.396 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 15 07 60 0D 01 01 25 01 00 25 7B E7 2020-04-24 18:47:35.402 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 01 25 01 00 25 7B E7 2020-04-24 18:47:35.404 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:35.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34170: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.409 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:35.412 [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-04-24 18:47:35.416 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23628 to 23629 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.418 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:35.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:35.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:35.425 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67168 to 67169 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34170: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:35.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:35.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34170: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:35.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34170: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.439 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:35.441 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: sentData successfully placed on stack. 2020-04-24 18:47:35.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34170: Advanced to WAIT_REQUEST 2020-04-24 18:47:35.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: TID 34170: Transaction not completed 2020-04-24 18:47:35.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:35.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:35.493 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7B 00 00 09 99 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:35.496 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67169 to 67170 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=123, payload=7B 00 00 09 2020-04-24 18:47:35.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=123, payload=7B 00 00 09 2020-04-24 18:47:35.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34170: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:35.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34170: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 123 2020-04-24 18:47:35.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34170: (Callback 123) 2020-04-24 18:47:35.505 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:35.506 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34170: callback 123 2020-04-24 18:47:35.507 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=123, payload=7B 00 00 09 2020-04-24 18:47:35.508 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: SendData Request. CallBack ID = 123, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:35.510 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34170: Transaction COMPLETED 2020-04-24 18:47:35.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Response processed after 105ms 2020-04-24 18:47:35.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: TID 34170: Transaction completed 2020-04-24 18:47:35.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:34170 DONE 2020-04-24 18:47:35.514 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:35.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:35.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:35.518 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 10 03 25 01 00 25 7C 88 2020-04-24 18:47:35.520 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 25 01 00 25 7C 88 2020-04-24 18:47:35.521 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:35.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:35.524 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:35.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:35.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:35.528 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23629 to 23630 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:35.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:35.531 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:35.532 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:35.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:35.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:35.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:35.538 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67170 to 67171 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:35.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:35.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:35.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:35.542 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:35.544 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack. 2020-04-24 18:47:35.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34171: Advanced to WAIT_REQUEST 2020-04-24 18:47:35.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction not completed 2020-04-24 18:47:35.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:35.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:40.546 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 16: TID 34171: Timeout at state WAIT_REQUEST. 3 retries remaining. 2020-04-24 18:47:40.548 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-04-24 18:47:40.550 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction ABORTED 2020-04-24 18:47:40.553 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-04-24 18:47:40.555 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-04-24 18:47:40.557 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:40.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:40.560 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:40.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:40.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:40.567 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23630 to 23631 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:40.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:40.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:40.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:40.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:40.731 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-04-24 18:47:40.827 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:47:40.841 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:41.181 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-04-24T18:46:41.151-0500 to 2020-04-24T18:47:41.156-0500 2020-04-24 18:47:41.184 [vent.ItemStateChangedEvent] - Current_date_time changed from 2020-04-24T18:46:41.151-0500 to 2020-04-24T18:47:41.156-0500 2020-04-24 18:47:41.186 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2020-04-24 18:46:41 CDT to 2020-04-24 18:47:41 CDT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:43.472 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7C 01 03 1A 8F 2020-04-24 18:47:43.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=124, payload=7C 01 03 1A 2020-04-24 18:47:43.479 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=124, payload=7C 01 03 1A 2020-04-24 18:47:43.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:43.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:43.480 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67171 to 67172 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:43.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 124 2020-04-24 18:47:43.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34171: (Callback 124) 2020-04-24 18:47:43.490 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:43.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34171: callback 124 2020-04-24 18:47:43.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=124, payload=7C 01 03 1A 2020-04-24 18:47:43.496 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 124, Status = Transmission complete, no ACK received(1) 2020-04-24 18:47:43.498 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction CANCELLED 2020-04-24 18:47:43.501 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:43.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: CANCEL while sending message. Requeueing - 2 attempts left! 2020-04-24 18:47:43.506 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction RESET with 2 retries remaining. 2020-04-24 18:47:43.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue 2020-04-24 18:47:43.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 34171 to queue - size 19 2020-04-24 18:47:43.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:43.516 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 10 03 25 01 00 25 7D 89 2020-04-24 18:47:43.519 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 25 01 00 25 7D 89 2020-04-24 18:47:43.521 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:43.525 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:43.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:43.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:43.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction not completed 2020-04-24 18:47:43.532 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:43.533 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23631 to 23632 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:43.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:43.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:43.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:43.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:44.444 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:44.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:44.448 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67172 to 67173 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:44.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:44.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:44.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:44.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:44.459 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:44.461 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack. 2020-04-24 18:47:44.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34171: Advanced to WAIT_REQUEST 2020-04-24 18:47:44.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction not completed 2020-04-24 18:47:44.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:49.465 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 16: TID 34171: Timeout at state WAIT_REQUEST. 2 retries remaining. 2020-04-24 18:47:49.467 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-04-24 18:47:49.468 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction ABORTED 2020-04-24 18:47:49.471 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-04-24 18:47:49.473 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-04-24 18:47:49.475 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:49.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:49.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:49.484 [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-04-24 18:47:49.485 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23632 to 23633 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:49.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:49.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:49.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:49.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:49.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:50.794 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7D 01 02 D6 43 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:50.797 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67173 to 67174 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:50.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 02 D6 2020-04-24 18:47:50.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 02 D6 2020-04-24 18:47:50.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:50.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:50.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [ABORTED] priority=Set, requiresResponse=true, callback: 125 2020-04-24 18:47:50.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34171: (Callback 125) 2020-04-24 18:47:50.818 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:50.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34171: callback 125 2020-04-24 18:47:50.824 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 02 D6 2020-04-24 18:47:50.827 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 125, Status = Transmission complete, no ACK received(1) 2020-04-24 18:47:50.830 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction CANCELLED 2020-04-24 18:47:50.833 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:50.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: CANCEL while sending message. Requeueing - 1 attempts left! 2020-04-24 18:47:50.839 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction RESET with 1 retries remaining. 2020-04-24 18:47:50.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue 2020-04-24 18:47:50.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 34171 to queue - size 19 2020-04-24 18:47:50.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:50.850 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 10 03 25 01 00 25 7E 8A 2020-04-24 18:47:50.853 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 25 01 00 25 7E 8A 2020-04-24 18:47:50.855 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:50.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:50.858 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:50.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction not completed 2020-04-24 18:47:50.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:50.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:50.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:50.868 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23633 to 23634 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:50.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:50.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:50.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:50.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:50.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:51.897 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:51.901 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67174 to 67175 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:51.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:51.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:51.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:51.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:51.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:51.916 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:51.918 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack. 2020-04-24 18:47:51.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34171: Advanced to WAIT_REQUEST 2020-04-24 18:47:51.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction not completed 2020-04-24 18:47:51.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:51.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.079 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7E 00 00 7A EF ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.082 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67175 to 67176 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=126, payload=7E 00 00 7A 2020-04-24 18:47:52.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=126, payload=7E 00 00 7A 2020-04-24 18:47:52.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34171: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:52.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34171: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 126 2020-04-24 18:47:52.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34171: (Callback 126) 2020-04-24 18:47:52.098 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:52.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34171: callback 126 2020-04-24 18:47:52.101 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=126, payload=7E 00 00 7A 2020-04-24 18:47:52.103 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 126, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:52.105 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34171: Transaction COMPLETED 2020-04-24 18:47:52.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Response processed after 1251ms 2020-04-24 18:47:52.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 34171: Transaction completed 2020-04-24 18:47:52.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:34171 DONE 2020-04-24 18:47:52.114 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:52.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:52.121 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0F 03 25 01 00 25 7F 94 2020-04-24 18:47:52.124 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 15: Sending REQUEST Message = 01 0A 00 13 0F 03 25 01 00 25 7F 94 2020-04-24 18:47:52.126 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:52.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34172: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.131 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:52.135 [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-04-24 18:47:52.137 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23634 to 23635 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.140 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:52.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34172: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.145 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.145 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67176 to 67177 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:52.152 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34172: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34172: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.159 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.161 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: sentData successfully placed on stack. 2020-04-24 18:47:52.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34172: Advanced to WAIT_REQUEST 2020-04-24 18:47:52.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 34172: Transaction not completed 2020-04-24 18:47:52.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.221 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7F 00 00 09 9D 2020-04-24 18:47:52.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=127, payload=7F 00 00 09 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.224 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67177 to 67178 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=127, payload=7F 00 00 09 2020-04-24 18:47:52.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34172: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34172: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 127 2020-04-24 18:47:52.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34172: (Callback 127) 2020-04-24 18:47:52.234 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:52.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34172: callback 127 2020-04-24 18:47:52.238 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=127, payload=7F 00 00 09 2020-04-24 18:47:52.240 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 15: SendData Request. CallBack ID = 127, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:52.241 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34172: Transaction COMPLETED 2020-04-24 18:47:52.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Response processed after 115ms 2020-04-24 18:47:52.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: TID 34172: Transaction completed 2020-04-24 18:47:52.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: notifyTransactionResponse TID:34172 DONE 2020-04-24 18:47:52.248 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:52.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:52.253 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 19 03 26 01 00 25 80 7E 2020-04-24 18:47:52.255 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 26 01 00 25 80 7E 2020-04-24 18:47:52.257 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:52.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34173: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.260 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:52.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.264 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23635 to 23636 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34173: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:52.267 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:52.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.272 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67178 to 67179 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34173: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34173: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.286 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.288 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: sentData successfully placed on stack. 2020-04-24 18:47:52.289 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34173: Advanced to WAIT_REQUEST 2020-04-24 18:47:52.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 34173: Transaction not completed 2020-04-24 18:47:52.292 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.294 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.350 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 80 00 00 09 62 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.353 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67179 to 67180 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=128, payload=80 00 00 09 2020-04-24 18:47:52.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=128, payload=80 00 00 09 2020-04-24 18:47:52.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34173: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34173: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 128 2020-04-24 18:47:52.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34173: (Callback 128) 2020-04-24 18:47:52.365 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:52.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34173: callback 128 2020-04-24 18:47:52.368 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=128, payload=80 00 00 09 2020-04-24 18:47:52.370 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 25: SendData Request. CallBack ID = 128, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:52.372 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34173: Transaction COMPLETED 2020-04-24 18:47:52.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Response processed after 116ms 2020-04-24 18:47:52.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: TID 34173: Transaction completed 2020-04-24 18:47:52.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: notifyTransactionResponse TID:34173 DONE 2020-04-24 18:47:52.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:52.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:52.385 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1A 03 26 01 00 25 81 7C 2020-04-24 18:47:52.387 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 26: Sending REQUEST Message = 01 0A 00 13 1A 03 26 01 00 25 81 7C 2020-04-24 18:47:52.389 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:52.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.393 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:52.396 [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-04-24 18:47:52.396 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23636 to 23637 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:52.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.403 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:52.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.408 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67180 to 67181 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.409 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.414 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.415 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: sentData successfully placed on stack. 2020-04-24 18:47:52.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34174: Advanced to WAIT_REQUEST 2020-04-24 18:47:52.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 34174: Transaction not completed 2020-04-24 18:47:52.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.503 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 81 00 00 0A 60 2020-04-24 18:47:52.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 0A ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.505 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67181 to 67182 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 0A 2020-04-24 18:47:52.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34174: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34174: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 129 2020-04-24 18:47:52.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34174: (Callback 129) 2020-04-24 18:47:52.515 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:52.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34174: callback 129 2020-04-24 18:47:52.517 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=129, payload=81 00 00 0A 2020-04-24 18:47:52.519 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: SendData Request. CallBack ID = 129, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:52.520 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34174: Transaction COMPLETED 2020-04-24 18:47:52.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Response processed after 130ms 2020-04-24 18:47:52.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 34174: Transaction completed 2020-04-24 18:47:52.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:34174 DONE 2020-04-24 18:47:52.526 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:52.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:52.531 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 18 03 26 01 00 25 82 7D 2020-04-24 18:47:52.533 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 0A 00 13 18 03 26 01 00 25 82 7D 2020-04-24 18:47:52.534 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:52.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34175: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.538 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:52.540 [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-04-24 18:47:52.541 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23637 to 23638 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34175: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:52.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.549 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67182 to 67183 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.551 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:52.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34175: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34175: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.561 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.563 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack. 2020-04-24 18:47:52.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34175: Advanced to WAIT_REQUEST 2020-04-24 18:47:52.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 34175: Transaction not completed 2020-04-24 18:47:52.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.652 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 82 00 00 0B 62 2020-04-24 18:47:52.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=130, payload=82 00 00 0B ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.654 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67183 to 67184 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=130, payload=82 00 00 0B 2020-04-24 18:47:52.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34175: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.661 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34175: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 130 2020-04-24 18:47:52.662 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34175: (Callback 130) 2020-04-24 18:47:52.664 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:52.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34175: callback 130 2020-04-24 18:47:52.667 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=130, payload=82 00 00 0B 2020-04-24 18:47:52.669 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 130, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:52.670 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34175: Transaction COMPLETED 2020-04-24 18:47:52.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Response processed after 136ms 2020-04-24 18:47:52.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 34175: Transaction completed 2020-04-24 18:47:52.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:34175 DONE 2020-04-24 18:47:52.676 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:52.677 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:52.680 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 17 03 26 01 00 25 83 73 2020-04-24 18:47:52.682 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 23: Sending REQUEST Message = 01 0A 00 13 17 03 26 01 00 25 83 73 2020-04-24 18:47:52.684 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:52.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34177: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 131 2020-04-24 18:47:52.686 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.690 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23638 to 23639 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.694 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:52.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:52.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34177: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 131 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:52.698 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67184 to 67185 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:52.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:52.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:52.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34177: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 131 2020-04-24 18:47:52.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:52.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34177: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 131 2020-04-24 18:47:52.710 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:52.711 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 23: sentData successfully placed on stack. 2020-04-24 18:47:52.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34177: Advanced to WAIT_REQUEST 2020-04-24 18:47:52.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: TID 34177: Transaction not completed 2020-04-24 18:47:52.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:52.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:53.143 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@f1e7b6 2020-04-24 18:47:53.145 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue 2020-04-24 18:47:53.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 34188 to queue - size 14 2020-04-24 18:47:53.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:53.200 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 83 00 00 33 5B ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.204 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67185 to 67186 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=131, payload=83 00 00 33 2020-04-24 18:47:53.210 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=131, payload=83 00 00 33 2020-04-24 18:47:53.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34177: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 131 2020-04-24 18:47:53.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:53.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34177: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 131 2020-04-24 18:47:53.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34177: (Callback 131) 2020-04-24 18:47:53.223 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:53.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34177: callback 131 2020-04-24 18:47:53.226 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=131, payload=83 00 00 33 2020-04-24 18:47:53.228 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 23: SendData Request. CallBack ID = 131, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:53.230 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34177: Transaction COMPLETED 2020-04-24 18:47:53.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: Response processed after 547ms 2020-04-24 18:47:53.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: TID 34177: Transaction completed 2020-04-24 18:47:53.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: notifyTransactionResponse TID:34177 DONE 2020-04-24 18:47:53.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:53.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:53.245 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 0D 07 60 0D 01 01 25 01 00 25 84 00 2020-04-24 18:47:53.248 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0E 00 13 0D 07 60 0D 01 01 25 01 00 25 84 00 2020-04-24 18:47:53.250 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:53.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34178: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.255 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.259 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23639 to 23640 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:53.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:53.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34178: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:53.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.274 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67186 to 67187 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.272 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:53.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:53.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:53.294 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34178: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:53.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34178: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.298 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:53.300 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: sentData successfully placed on stack. 2020-04-24 18:47:53.301 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34178: Advanced to WAIT_REQUEST 2020-04-24 18:47:53.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 34178: Transaction not completed 2020-04-24 18:47:53.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:53.324 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 84 00 00 07 68 2020-04-24 18:47:53.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=132, payload=84 00 00 07 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.327 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67187 to 67188 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=132, payload=84 00 00 07 2020-04-24 18:47:53.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34178: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:53.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34178: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 132 2020-04-24 18:47:53.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34178: (Callback 132) 2020-04-24 18:47:53.335 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:53.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34178: callback 132 2020-04-24 18:47:53.338 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=132, payload=84 00 00 07 2020-04-24 18:47:53.339 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 132, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:53.340 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34178: Transaction COMPLETED 2020-04-24 18:47:53.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Response processed after 89ms 2020-04-24 18:47:53.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 34178: Transaction completed 2020-04-24 18:47:53.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:34178 DONE 2020-04-24 18:47:53.345 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:53.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:53.349 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 11 03 25 01 00 25 85 70 2020-04-24 18:47:53.351 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 17: Sending REQUEST Message = 01 0A 00 13 11 03 25 01 00 25 85 70 2020-04-24 18:47:53.352 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:53.355 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:53.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34179: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.357 [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-04-24 18:47:53.359 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23640 to 23641 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:53.362 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:53.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34179: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:53.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:53.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:53.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.369 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67188 to 67189 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34179: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:53.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34179: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.376 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:53.378 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: sentData successfully placed on stack. 2020-04-24 18:47:53.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34179: Advanced to WAIT_REQUEST 2020-04-24 18:47:53.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: TID 34179: Transaction not completed 2020-04-24 18:47:53.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:53.877 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 85 00 00 34 5A 2020-04-24 18:47:53.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 34 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:53.880 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67189 to 67190 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 34 2020-04-24 18:47:53.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34179: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:53.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34179: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 133 2020-04-24 18:47:53.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34179: (Callback 133) 2020-04-24 18:47:53.890 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:53.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34179: callback 133 2020-04-24 18:47:53.893 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=133, payload=85 00 00 34 2020-04-24 18:47:53.894 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:53.896 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34179: Transaction COMPLETED 2020-04-24 18:47:53.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Response processed after 544ms 2020-04-24 18:47:53.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: TID 34179: Transaction completed 2020-04-24 18:47:53.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: notifyTransactionResponse TID:34179 DONE 2020-04-24 18:47:53.903 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:53.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:53.908 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 25 01 00 25 86 0D 2020-04-24 18:47:53.910 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 25 01 00 25 86 0D 2020-04-24 18:47:53.912 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:53.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34180: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:53.917 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:53.918 [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-04-24 18:47:53.921 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23641 to 23642 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:53.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:53.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34180: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:53.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:53.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:53.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:54.098 [DEBUG] [overy.OpenWeatherMapDiscoveryService] - Location is not set -> Will not provide any discovery results. 2020-04-24 18:47:54.599 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:54.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34180: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:54.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.609 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67190 to 67191 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34180: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:54.613 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.615 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack. 2020-04-24 18:47:54.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34180: Advanced to WAIT_REQUEST 2020-04-24 18:47:54.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 34180: Transaction not completed 2020-04-24 18:47:54.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:54.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:54.823 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 86 00 00 5A 37 2020-04-24 18:47:54.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 5A ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.828 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67191 to 67192 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 5A 2020-04-24 18:47:54.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34180: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:54.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:54.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34180: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 134 2020-04-24 18:47:54.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34180: (Callback 134) 2020-04-24 18:47:54.839 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:54.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34180: callback 134 2020-04-24 18:47:54.843 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=134, payload=86 00 00 5A 2020-04-24 18:47:54.845 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 134, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:54.847 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent 2020-04-24 18:47:54.849 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting ONLINE 2020-04-24 18:47:54.855 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is ALIVE 2020-04-24 18:47:54.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is ALIVE. Init stage is SUC_ROUTE. 2020-04-24 18:47:54.859 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent 2020-04-24 18:47:54.861 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting ONLINE ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.861 [hingStatusInfoChangedEvent] - 'zwave:device:894dd1c6:node2' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.864 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is ALIVE 2020-04-24 18:47:54.866 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34180: Transaction COMPLETED 2020-04-24 18:47:54.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Response processed after 954ms 2020-04-24 18:47:54.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 34180: Transaction completed 2020-04-24 18:47:54.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:34180 DONE 2020-04-24 18:47:54.875 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:54.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:54.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:54.881 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 16 03 26 01 00 25 87 76 2020-04-24 18:47:54.884 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 22: Sending REQUEST Message = 01 0A 00 13 16 03 26 01 00 25 87 76 2020-04-24 18:47:54.886 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:54.889 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:54.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34181: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:54.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.896 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23642 to 23643 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.897 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:54.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34181: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:54.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.905 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67192 to 67193 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:54.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34181: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:54.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34181: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.921 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:54.923 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 22: sentData successfully placed on stack. 2020-04-24 18:47:54.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34181: Advanced to WAIT_REQUEST 2020-04-24 18:47:54.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: TID 34181: Transaction not completed 2020-04-24 18:47:54.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:54.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:54.956 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 87 00 00 07 6B 2020-04-24 18:47:54.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 07 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.960 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67193 to 67194 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 07 2020-04-24 18:47:54.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34181: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:54.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34181: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 135 2020-04-24 18:47:54.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34181: (Callback 135) 2020-04-24 18:47:54.969 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:54.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34181: callback 135 2020-04-24 18:47:54.972 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=135, payload=87 00 00 07 2020-04-24 18:47:54.973 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 22: SendData Request. CallBack ID = 135, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:54.974 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34181: Transaction COMPLETED 2020-04-24 18:47:54.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: Response processed after 87ms 2020-04-24 18:47:54.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: TID 34181: Transaction completed 2020-04-24 18:47:54.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: notifyTransactionResponse TID:34181 DONE 2020-04-24 18:47:54.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:54.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:54.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:54.984 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 0B 07 60 0D 01 01 25 01 00 25 88 0A 2020-04-24 18:47:54.986 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0E 00 13 0B 07 60 0D 01 01 25 01 00 25 88 0A 2020-04-24 18:47:54.987 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:54.990 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:54.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34182: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:54.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:54.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:54.995 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23643 to 23644 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:54.997 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:54.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34182: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:54.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:55.001 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67194 to 67195 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:55.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:54.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:55.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:55.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:55.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34182: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:55.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:55.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34182: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:55.010 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:55.011 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: sentData successfully placed on stack. 2020-04-24 18:47:55.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34182: Advanced to WAIT_REQUEST 2020-04-24 18:47:55.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: TID 34182: Transaction not completed 2020-04-24 18:47:55.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:55.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:55.071 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 88 00 00 08 6B ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:55.073 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67195 to 67196 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:55.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=136, payload=88 00 00 08 2020-04-24 18:47:55.076 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=136, payload=88 00 00 08 2020-04-24 18:47:55.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34182: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:55.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:55.080 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34182: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 136 2020-04-24 18:47:55.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34182: (Callback 136) 2020-04-24 18:47:55.083 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:55.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34182: callback 136 2020-04-24 18:47:55.086 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=136, payload=88 00 00 08 2020-04-24 18:47:55.087 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 136, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:55.089 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34182: Transaction COMPLETED 2020-04-24 18:47:55.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Response processed after 102ms 2020-04-24 18:47:55.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: TID 34182: Transaction completed 2020-04-24 18:47:55.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: notifyTransactionResponse TID:34182 DONE 2020-04-24 18:47:55.094 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:55.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:55.097 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:55.099 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 04 03 26 01 00 25 89 6A 2020-04-24 18:47:55.101 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0A 00 13 04 03 26 01 00 25 89 6A 2020-04-24 18:47:55.103 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:55.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:55.106 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:55.108 [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-04-24 18:47:55.108 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23644 to 23645 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:55.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:55.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:55.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:55.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:55.115 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:55.788 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:55.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:55.792 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67196 to 67197 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:55.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:55.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:55.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:55.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:55.803 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:55.806 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack. 2020-04-24 18:47:55.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34183: Advanced to WAIT_REQUEST 2020-04-24 18:47:55.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 34183: Transaction not completed 2020-04-24 18:47:55.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:55.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:56.742 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:56.760 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 279.43546456059033 to 279.59695749311663 2020-04-24 18:47:56.764 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 9.24692012002811 to 9.062818016662662 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:56.978 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:56.989 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 267.9811353994675 to 268.14760044291035 2020-04-24 18:47:56.991 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 26.550100741742998 to 26.36980622352325 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.134 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 89 00 01 93 F0 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.138 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67197 to 67198 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=137, payload=89 00 01 93 2020-04-24 18:47:59.140 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=137, payload=89 00 01 93 2020-04-24 18:47:59.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34183: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:59.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:59.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34183: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 137 2020-04-24 18:47:59.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34183: (Callback 137) 2020-04-24 18:47:59.150 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:59.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34183: callback 137 2020-04-24 18:47:59.154 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=137, payload=89 00 01 93 2020-04-24 18:47:59.156 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 137, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:59.158 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34183: Transaction COMPLETED 2020-04-24 18:47:59.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Response processed after 4055ms 2020-04-24 18:47:59.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 34183: Transaction completed 2020-04-24 18:47:59.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:34183 DONE 2020-04-24 18:47:59.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:59.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:59.172 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 14 07 60 0D 01 01 25 01 00 25 8A 17 2020-04-24 18:47:59.174 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 20: Sending REQUEST Message = 01 0E 00 13 14 07 60 0D 01 01 25 01 00 25 8A 17 2020-04-24 18:47:59.177 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:59.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34184: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.181 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:59.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:59.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.186 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23645 to 23646 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34184: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.189 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:59.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:59.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.194 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67198 to 67199 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:59.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:59.199 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34184: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:59.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34184: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.203 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:59.205 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: sentData successfully placed on stack. 2020-04-24 18:47:59.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34184: Advanced to WAIT_REQUEST 2020-04-24 18:47:59.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 34184: Transaction not completed 2020-04-24 18:47:59.209 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.210 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:59.266 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8A 00 00 09 68 2020-04-24 18:47:59.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=138, payload=8A 00 00 09 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.268 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67199 to 67200 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=138, payload=8A 00 00 09 2020-04-24 18:47:59.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34184: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:59.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34184: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 138 2020-04-24 18:47:59.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34184: (Callback 138) 2020-04-24 18:47:59.276 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:59.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34184: callback 138 2020-04-24 18:47:59.278 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=138, payload=8A 00 00 09 2020-04-24 18:47:59.279 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: SendData Request. CallBack ID = 138, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:59.281 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34184: Transaction COMPLETED 2020-04-24 18:47:59.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Response processed after 104ms 2020-04-24 18:47:59.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 34184: Transaction completed 2020-04-24 18:47:59.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:34184 DONE 2020-04-24 18:47:59.285 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:59.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:59.290 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 06 03 26 01 00 25 8B 6A 2020-04-24 18:47:59.292 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 0A 00 13 06 03 26 01 00 25 8B 6A 2020-04-24 18:47:59.293 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:59.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34185: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.296 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:59.297 [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-04-24 18:47:59.299 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23646 to 23647 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:59.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34185: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.303 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:47:59.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:59.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.306 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67200 to 67201 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:59.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:59.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34185: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:59.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34185: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.321 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:47:59.323 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: sentData successfully placed on stack. 2020-04-24 18:47:59.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34185: Advanced to WAIT_REQUEST 2020-04-24 18:47:59.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 34185: Transaction not completed 2020-04-24 18:47:59.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:47:59.386 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8B 00 00 09 69 2020-04-24 18:47:59.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=139, payload=8B 00 00 09 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.388 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67201 to 67202 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=139, payload=8B 00 00 09 2020-04-24 18:47:59.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34185: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:47:59.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34185: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 139 2020-04-24 18:47:59.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34185: (Callback 139) 2020-04-24 18:47:59.398 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:47:59.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34185: callback 139 2020-04-24 18:47:59.402 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=139, payload=8B 00 00 09 2020-04-24 18:47:59.404 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 139, Status = Transmission complete and ACK received(0) 2020-04-24 18:47:59.406 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34185: Transaction COMPLETED 2020-04-24 18:47:59.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Response processed after 113ms 2020-04-24 18:47:59.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 34185: Transaction completed 2020-04-24 18:47:59.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: notifyTransactionResponse TID:34185 DONE 2020-04-24 18:47:59.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:47:59.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:47:59.421 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 08 03 26 01 00 25 8C 63 2020-04-24 18:47:59.424 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 26 01 00 25 8C 63 2020-04-24 18:47:59.426 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:47:59.429 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:47:59.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:59.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34186: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 140 2020-04-24 18:47:59.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:47:59.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34186: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 140 ==> /var/log/openhab2/events.log <== 2020-04-24 18:47:59.437 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23647 to 23648 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:47:59.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:47:59.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:47:59.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:48:00.015 [INFO ] [e.smarthome.model.script.Time of Day] - Calculating time of day... 2020-04-24 18:48:00.107 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.111 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67202 to 67203 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.115 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34186: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 140 2020-04-24 18:48:00.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:48:00.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34186: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 140 2020-04-24 18:48:00.121 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.123 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: sentData successfully placed on stack. 2020-04-24 18:48:00.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34186: Advanced to WAIT_REQUEST 2020-04-24 18:48:00.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: TID 34186: Transaction not completed 2020-04-24 18:48:00.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.127 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated time of day is EVENING1 2020-04-24 18:48:00.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:48:00.134 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated light / dark outside is LIGHT 2020-04-24 18:48:00.139 [INFO ] [e.smarthome.model.script.Time of Day] - Weather_OWM_Temperature 45.59 °F 2020-04-24 18:48:00.144 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature Item NULL 2020-04-24 18:48:00.149 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature State Item NULL 2020-04-24 18:48:00.152 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8C 00 00 48 2F 2020-04-24 18:48:00.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=140, payload=8C 00 00 48 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.160 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING1 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=140, payload=8C 00 00 48 2020-04-24 18:48:00.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34186: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 140 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.161 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67203 to 67204 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:48:00.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34186: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 140 2020-04-24 18:48:00.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34186: (Callback 140) 2020-04-24 18:48:00.167 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:48:00.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34186: callback 140 2020-04-24 18:48:00.170 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=140, payload=8C 00 00 48 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.170 [ome.event.ItemCommandEvent] - Item 'vLightOutside' received command LIGHT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.171 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: SendData Request. CallBack ID = 140, Status = Transmission complete and ACK received(0) 2020-04-24 18:48:00.173 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34186: Transaction COMPLETED 2020-04-24 18:48:00.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Response processed after 740ms 2020-04-24 18:48:00.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: TID 34186: Transaction completed 2020-04-24 18:48:00.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: notifyTransactionResponse TID:34186 DONE 2020-04-24 18:48:00.178 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:00.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:00.182 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 09 03 25 01 00 25 8D 60 2020-04-24 18:48:00.183 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 0A 00 13 09 03 25 01 00 25 8D 60 2020-04-24 18:48:00.185 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:00.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34187: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 141 2020-04-24 18:48:00.187 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:48:00.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:48:00.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:48:00.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34187: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 141 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.192 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23648 to 23649 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:48:00.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.196 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2020-04-24 18:48:00.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.199 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67204 to 67205 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34187: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 141 2020-04-24 18:48:00.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:48:00.207 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34187: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 141 2020-04-24 18:48:00.209 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2020-04-24 18:48:00.210 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: sentData successfully placed on stack. 2020-04-24 18:48:00.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34187: Advanced to WAIT_REQUEST 2020-04-24 18:48:00.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: TID 34187: Transaction not completed 2020-04-24 18:48:00.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.215 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:48:00.336 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 8D 00 00 0F 69 2020-04-24 18:48:00.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=141, payload=8D 00 00 0F ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.339 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_sof changed from 67205 to 67206 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=141, payload=8D 00 00 0F 2020-04-24 18:48:00.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34187: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 141 2020-04-24 18:48:00.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2020-04-24 18:48:00.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 34187: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 141 2020-04-24 18:48:00.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 34187: (Callback 141) 2020-04-24 18:48:00.349 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2020-04-24 18:48:00.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 34187: callback 141 2020-04-24 18:48:00.352 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=141, payload=8D 00 00 0F 2020-04-24 18:48:00.353 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 141, Status = Transmission complete and ACK received(0) 2020-04-24 18:48:00.355 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34187: Transaction COMPLETED 2020-04-24 18:48:00.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Response processed after 170ms 2020-04-24 18:48:00.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: TID 34187: Transaction completed 2020-04-24 18:48:00.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: notifyTransactionResponse TID:34187 DONE 2020-04-24 18:48:00.361 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:00.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:00.365 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 0D 76 D0 2020-04-24 18:48:00.366 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 0D 76 D0 2020-04-24 18:48:00.368 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:00.370 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2020-04-24 18:48:00.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34164: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 118 ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:00.373 [vent.ItemStateChangedEvent] - zwave_serial_zstick_894dd1c6_serial_ack changed from 23649 to 23650 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:00.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:48:00.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2020-04-24 18:48:00.379 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 34164: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 118 2020-04-24 18:48:00.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2020-04-24 18:48:00.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2020-04-24 18:48:00.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:48:02.373 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 13: TID 34164: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:48:02.375 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34164: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:48:02.377 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34164: Transaction CANCELLED 2020-04-24 18:48:02.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:02.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: notifyTransactionResponse TID:34164 CANCELLED 2020-04-24 18:48:02.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:02.386 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 1A 8E 3F 2020-04-24 18:48:02.389 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 1A 8E 3F 2020-04-24 18:48:02.392 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:02.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34165: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 142 2020-04-24 18:48:04.395 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 26: TID 34165: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:48:04.397 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34165: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:48:04.399 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34165: Transaction CANCELLED 2020-04-24 18:48:04.401 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:04.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:34165 CANCELLED 2020-04-24 18:48:04.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:04.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34165: Transaction event listener: DONE: CANCELLED -> 2020-04-24 18:48:04.408 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 14 8F 30 2020-04-24 18:48:04.409 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@11efe24 2020-04-24 18:48:04.411 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 14 8F 30 2020-04-24 18:48:04.414 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:04.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34176: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 143 2020-04-24 18:48:06.418 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 20: TID 34176: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:48:06.420 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34176: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:48:06.423 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34176: Transaction CANCELLED 2020-04-24 18:48:06.425 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:06.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:34176 CANCELLED 2020-04-24 18:48:06.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:06.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34176: Transaction event listener: DONE: CANCELLED -> 2020-04-24 18:48:06.433 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 20: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@f7e613 2020-04-24 18:48:06.435 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 18 90 23 2020-04-24 18:48:06.438 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 18 90 23 2020-04-24 18:48:06.440 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:06.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34188: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 144 2020-04-24 18:48:08.444 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 24: TID 34188: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:48:08.446 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34188: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:48:08.449 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34188: Transaction CANCELLED 2020-04-24 18:48:08.451 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:08.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:34188 CANCELLED 2020-04-24 18:48:08.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:08.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34188: Transaction event listener: DONE: CANCELLED -> 2020-04-24 18:48:08.458 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@151120b 2020-04-24 18:48:10.830 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:48:40.736 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-04-24 18:48:40.833 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:48:40.846 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:41.170 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-04-24T18:47:41.156-0500 to 2020-04-24T18:48:41.159-0500 2020-04-24 18:48:41.172 [vent.ItemStateChangedEvent] - Current_date_time changed from 2020-04-24T18:47:41.156-0500 to 2020-04-24T18:48:41.159-0500 2020-04-24 18:48:41.174 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2020-04-24 18:47:41 CDT to 2020-04-24 18:48:41 CDT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:46.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6c7d58 2020-04-24 18:48:46.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Adding to device queue 2020-04-24 18:48:46.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Added 34189 to queue - size 1 2020-04-24 18:48:46.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:46.018 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 20 91 1A 2020-04-24 18:48:46.020 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 20 91 1A 2020-04-24 18:48:46.023 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:48:46.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34189: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 145 2020-04-24 18:48:48.028 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 32: TID 34189: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:48:48.030 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34189: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:48:48.032 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34189: Transaction CANCELLED 2020-04-24 18:48:48.034 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:48:48.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: notifyTransactionResponse TID:34189 CANCELLED 2020-04-24 18:48:48.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:48:48.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34189: Transaction event listener: DONE: CANCELLED -> 2020-04-24 18:48:48.041 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 32: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@b0a6bd 2020-04-24 18:48:54.101 [DEBUG] [overy.OpenWeatherMapDiscoveryService] - Location is not set -> Will not provide any discovery results. 2020-04-24 18:48:56.728 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:56.762 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 279.59695749311663 to 279.75837853880455 2020-04-24 18:48:56.764 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 9.062818016662662 to 8.878908005756303 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:48:56.967 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:48:56.980 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 268.14760044291035 to 268.31373315053156 2020-04-24 18:48:56.981 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 26.36980622352325 to 26.189545032220742 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:49:00.015 [INFO ] [e.smarthome.model.script.Time of Day] - Calculating time of day... 2020-04-24 18:49:00.117 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated time of day is EVENING1 2020-04-24 18:49:00.121 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated light / dark outside is LIGHT 2020-04-24 18:49:00.126 [INFO ] [e.smarthome.model.script.Time of Day] - Weather_OWM_Temperature 45.59 °F 2020-04-24 18:49:00.130 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature Item NULL 2020-04-24 18:49:00.135 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature State Item NULL ==> /var/log/openhab2/events.log <== 2020-04-24 18:49:00.144 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING1 2020-04-24 18:49:00.150 [ome.event.ItemCommandEvent] - Item 'vLightOutside' received command LIGHT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:49:10.836 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:49:27.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@140b31b 2020-04-24 18:49:27.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue 2020-04-24 18:49:27.929 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 34190 to queue - size 1 2020-04-24 18:49:27.931 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:49:27.934 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 51 10 92 29 2020-04-24 18:49:27.937 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 51 10 92 29 2020-04-24 18:49:27.940 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:49:27.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34190: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 146 2020-04-24 18:49:30.018 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 16: TID 34190: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:49:30.067 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34190: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:49:30.069 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34190: Transaction CANCELLED 2020-04-24 18:49:30.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:49:30.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:34190 CANCELLED 2020-04-24 18:49:30.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:49:30.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 34190: Transaction event listener: DONE: CANCELLED -> 2020-04-24 18:49:30.081 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 16: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@6e61c2 2020-04-24 18:49:40.745 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-04-24 18:49:40.840 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:49:40.844 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed ==> /var/log/openhab2/events.log <== 2020-04-24 18:49:41.175 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-04-24T18:48:41.159-0500 to 2020-04-24T18:49:41.162-0500 2020-04-24 18:49:41.177 [vent.ItemStateChangedEvent] - Current_date_time changed from 2020-04-24T18:48:41.159-0500 to 2020-04-24T18:49:41.162-0500 2020-04-24 18:49:41.179 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2020-04-24 18:48:41 CDT to 2020-04-24 18:49:41 CDT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:49:54.103 [DEBUG] [overy.OpenWeatherMapDiscoveryService] - Location is not set -> Will not provide any discovery results. 2020-04-24 18:49:56.724 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:49:56.768 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 279.75837853880455 to 279.9198467102484 2020-04-24 18:49:56.772 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 8.878908005756303 to 8.695059646367993 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:49:56.967 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:49:56.979 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 268.31373315053156 to 268.4796020600549 2020-04-24 18:49:56.984 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 26.189545032220742 to 26.009249558944955 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:00.021 [INFO ] [e.smarthome.model.script.Time of Day] - Calculating time of day... 2020-04-24 18:50:00.028 [INFO ] [smarthome.model.script.Update States] - Running Update house at: 2020-04-24T18:50:00.026-05:00 2020-04-24 18:50:00.036 [INFO ] [smarthome.model.script.Update States] - Occupancy Mode is NULL. 2020-04-24 18:50:00.044 [INFO ] [smarthome.model.script.Update States] - Owner Home is NULL. 2020-04-24 18:50:00.053 [INFO ] [smarthome.model.script.Update States] - Anyone Home is NULL. 2020-04-24 18:50:00.062 [INFO ] [smarthome.model.script.Update States] - Chamber Level Occupied NULL. 2020-04-24 18:50:00.071 [INFO ] [smarthome.model.script.Update States] - Inside House Lighting Scene LT_ALLOFF. 2020-04-24 18:50:00.078 [INFO ] [smarthome.model.script.Update States] - Outside House Lighting Scene NULL. 2020-04-24 18:50:00.086 [INFO ] [smarthome.model.script.Update States] - Rear Terrace Lighting Scene NULL. 2020-04-24 18:50:00.095 [INFO ] [smarthome.model.script.Update States] - Time of Day EVENING1. 2020-04-24 18:50:00.104 [INFO ] [smarthome.model.script.Update States] - Light or Dark Outside LIGHT. 2020-04-24 18:50:00.111 [INFO ] [smarthome.model.script.Update States] - Last Audio Volume Change is 2020-04-24T18:00:40.772-0500. 2020-04-24 18:50:00.118 [INFO ] [smarthome.model.script.Update States] - Last Audio Scene Change is 2020-04-24T02:40:32.223-0500. 2020-04-24 18:50:00.122 [INFO ] [smarthome.model.script.Update States] - Audio Volume is OFF. 2020-04-24 18:50:00.135 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated time of day is EVENING1 2020-04-24 18:50:00.138 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated light / dark outside is LIGHT 2020-04-24 18:50:00.138 [INFO ] [smarthome.model.script.Update States] - Last Audio Volume Change is 49 minutes ago. 2020-04-24 18:50:00.144 [INFO ] [e.smarthome.model.script.Time of Day] - Weather_OWM_Temperature 45.59 °F 2020-04-24 18:50:00.148 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature Item NULL 2020-04-24 18:50:00.154 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature State Item NULL 2020-04-24 18:50:00.159 [INFO ] [smarthome.model.script.Update States] - Last House Motion.state is 7 ago. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:00.171 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING1 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:00.171 [INFO ] [smarthome.model.script.Update States] - Basic Amplifiers are ON. 2020-04-24 18:50:00.178 [INFO ] [smarthome.model.script.Update States] - Last Entrance Motion.state is null at 2020-04-24T18:50:00.177-05:00 ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:00.192 [ome.event.ItemCommandEvent] - Item 'vLightOutside' received command LIGHT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:00.204 [INFO ] [smarthome.model.script.Update States] - Last_Basement_Motion.state is 678 ago. 2020-04-24 18:50:00.210 [INFO ] [smarthome.model.script.Update States] - Turning off basement lights. Minutes to shut off set at: 45 2020-04-24 18:50:00.225 [INFO ] [smarthome.model.script.Update States] - Last_Main_Level_Motion.state is 7 ago. 2020-04-24 18:50:00.230 [INFO ] [smarthome.model.script.Update States] - Last_Master_Level_Motion.state is null at 2020-04-24T18:50:00.230-05:00 2020-04-24 18:50:10.845 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:50:40.751 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-04-24 18:50:40.835 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed 2020-04-24 18:50:40.848 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:41.179 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-04-24T18:49:41.162-0500 to 2020-04-24T18:50:41.165-0500 2020-04-24 18:50:41.182 [vent.ItemStateChangedEvent] - Current_date_time changed from 2020-04-24T18:49:41.162-0500 to 2020-04-24T18:50:41.165-0500 2020-04-24 18:50:41.184 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2020-04-24 18:49:41 CDT to 2020-04-24 18:50:41 CDT 2020-04-24 18:50:47.677 [ome.event.ItemCommandEvent] - Item 'Inside_House_Lighting_Scene' received command LT_ALLON 2020-04-24 18:50:47.683 [vent.ItemStateChangedEvent] - Inside_House_Lighting_Scene changed from LT_ALLOFF to LT_ALLON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.729 [DEBUG] [ap.internal.MapTransformationService] - Transformation resulted in 'All Inside Lights On' ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.734 [ome.event.ItemCommandEvent] - Item 'ML_LivingRoom_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.768 [DEBUG] [ap.internal.MapTransformationService] - Transformation resulted in 'All Inside Lights On' ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.786 [ome.event.ItemCommandEvent] - Item 'ML_LivingRoom_Dimmer2' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Command received zwave:device:894dd1c6:node27:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.795 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 27: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:47.797 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: SECURITY not supported 2020-04-24 18:50:47.799 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 27: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:47.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: Adding to device queue 2020-04-24 18:50:47.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: Added 34191 to queue - size 1 2020-04-24 18:50:47.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.807 [ome.event.ItemCommandEvent] - Item 'ML_Kitchen_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.812 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1B 03 26 01 63 25 93 0C 2020-04-24 18:50:47.819 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 27: Sending REQUEST Message = 01 0A 00 13 1B 03 26 01 63 25 93 0C 2020-04-24 18:50:47.822 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Command received zwave:device:894dd1c6:node28:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.823 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:50:47.824 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 28: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:47.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 34191: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 147 2020-04-24 18:50:47.828 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.830 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: SECURITY not supported 2020-04-24 18:50:47.832 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:47.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Adding to device queue 2020-04-24 18:50:47.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Added 34192 to queue - size 1 ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.836 [ome.event.ItemCommandEvent] - Item 'ML_Kitchen_Dimmer2' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.842 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:894dd1c6:node19:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.844 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 19: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:47.846 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported 2020-04-24 18:50:47.848 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:47.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Adding to device queue 2020-04-24 18:50:47.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Added 34193 to queue - size 2 2020-04-24 18:50:47.854 [DEBUG] [ap.internal.MapTransformationService] - Transformation resulted in 'All Inside Lights On' 2020-04-24 18:50:47.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.877 [ome.event.ItemCommandEvent] - Item 'ML_Pantry_Switch' received command ON 2020-04-24 18:50:47.879 [nt.ItemStatePredictedEvent] - ML_LivingRoom_Dimmer1 predicted to become 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.882 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Command received zwave:device:894dd1c6:node18:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.884 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:47.886 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported 2020-04-24 18:50:47.888 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:47.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue 2020-04-24 18:50:47.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Added 34194 to queue - size 3 2020-04-24 18:50:47.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.895 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:894dd1c6:node21:switch_binary1 --> ON [OnOffType] 2020-04-24 18:50:47.899 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:47.901 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 1 2020-04-24 18:50:47.903 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:50:47.905 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: SECURITY not supported 2020-04-24 18:50:47.906 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:50:47.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue 2020-04-24 18:50:47.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Added 34195 to queue - size 4 2020-04-24 18:50:47.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.914 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.921 [ome.event.ItemCommandEvent] - Item 'ML_Kitchen_Bar_Lights' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.936 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:894dd1c6:node16:switch_binary --> ON [OnOffType] 2020-04-24 18:50:47.937 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 16: Creating new message for application command SWITCH_BINARY_SET ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.938 [ome.event.ItemCommandEvent] - Item 'ML_Kitchen_Sconce_Lights' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.939 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported 2020-04-24 18:50:47.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 2020-04-24 18:50:47.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue 2020-04-24 18:50:47.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 34196 to queue - size 5 2020-04-24 18:50:47.945 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.955 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Command received zwave:device:894dd1c6:node15:switch_binary --> ON [OnOffType] 2020-04-24 18:50:47.957 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 15: Creating new message for application command SWITCH_BINARY_SET ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.958 [ome.event.ItemCommandEvent] - Item 'ML_Hallway_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.959 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: SECURITY not supported 2020-04-24 18:50:47.962 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 2020-04-24 18:50:47.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue 2020-04-24 18:50:47.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Added 34197 to queue - size 6 2020-04-24 18:50:47.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.974 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Command received zwave:device:894dd1c6:node26:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.976 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 26: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.979 [ome.event.ItemCommandEvent] - Item 'ML_Hallway_Dimmer2' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:47.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:47.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue 2020-04-24 18:50:47.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Added 34198 to queue - size 7 2020-04-24 18:50:47.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:47.989 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:47.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Command received zwave:device:894dd1c6:node25:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:47.998 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 25: Creating new message for command SWITCH_MULTILEVEL_SET ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:47.998 [ome.event.ItemCommandEvent] - Item 'ML_Hallway_Dimmer3' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.000 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported 2020-04-24 18:50:48.002 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Adding to device queue 2020-04-24 18:50:48.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Added 34199 to queue - size 8 2020-04-24 18:50:48.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.017 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Command received zwave:device:894dd1c6:node24:switch_dimmer --> 100 [PercentType] ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.018 [ome.event.ItemCommandEvent] - Item 'ML_Hallway_Dimmer4' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.019 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 24: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:48.021 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported 2020-04-24 18:50:48.023 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue 2020-04-24 18:50:48.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 34200 to queue - size 9 2020-04-24 18:50:48.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.032 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.035 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Command received zwave:device:894dd1c6:node23:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:48.038 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 23: Creating new message for command SWITCH_MULTILEVEL_SET ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.038 [ome.event.ItemCommandEvent] - Item 'ML_DiningRoom_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.039 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 23: SECURITY not supported ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.039 [nt.ItemStatePredictedEvent] - ML_LivingRoom_Dimmer2 predicted to become 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.041 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 23: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: Adding to device queue 2020-04-24 18:50:48.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: Added 34201 to queue - size 10 2020-04-24 18:50:48.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.048 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.058 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Command received zwave:device:894dd1c6:node22:switch_dimmer --> 100 [PercentType] ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.059 [ome.event.ItemCommandEvent] - Item 'ML_GameBathroom_Switch' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.060 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 22: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:48.062 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: SECURITY not supported 2020-04-24 18:50:48.064 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 22: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: Adding to device queue 2020-04-24 18:50:48.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 22: Added 34202 to queue - size 11 2020-04-24 18:50:48.070 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.078 [ome.event.ItemCommandEvent] - Item 'ML_PowderRoom_Switch' received command ON 2020-04-24 18:50:48.093 [ome.event.ItemCommandEvent] - Item 'ML_MudRoom_Lights' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.093 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:894dd1c6:node13:switch_binary1 --> ON [OnOffType] 2020-04-24 18:50:48.094 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 13: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:48.096 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Encapsulating message, instance / endpoint 1 2020-04-24 18:50:48.097 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 13: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:50:48.099 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: SECURITY not supported 2020-04-24 18:50:48.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 13: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:50:48.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue 2020-04-24 18:50:48.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 34203 to queue - size 12 2020-04-24 18:50:48.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.107 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.109 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Command received zwave:device:894dd1c6:node17:switch_binary --> ON [OnOffType] 2020-04-24 18:50:48.111 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 17: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:48.112 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: SECURITY not supported 2020-04-24 18:50:48.114 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.114 [ome.event.ItemCommandEvent] - Item 'ML_Garage_Switch' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.115 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Adding to device queue 2020-04-24 18:50:48.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Added 34204 to queue - size 13 2020-04-24 18:50:48.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.120 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.131 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Command received zwave:device:894dd1c6:node20:switch_binary1 --> ON [OnOffType] 2020-04-24 18:50:48.132 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 20: Creating new message for application command SWITCH_BINARY_SET ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.133 [ome.event.ItemCommandEvent] - Item 'BS_Hallway_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.134 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Encapsulating message, instance / endpoint 1 ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.135 [nt.ItemStatePredictedEvent] - ML_Kitchen_Dimmer1 predicted to become 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.136 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 20: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:50:48.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY not supported 2020-04-24 18:50:48.140 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:50:48.142 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Adding to device queue 2020-04-24 18:50:48.145 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Added 34205 to queue - size 14 2020-04-24 18:50:48.147 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.154 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:894dd1c6:node4:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:48.157 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:48.159 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported 2020-04-24 18:50:48.162 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue 2020-04-24 18:50:48.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 34206 to queue - size 15 2020-04-24 18:50:48.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.169 [ome.event.ItemCommandEvent] - Item 'BS_MainRoom_Switch1' received command ON 2020-04-24 18:50:48.171 [nt.ItemStatePredictedEvent] - ML_Kitchen_Dimmer2 predicted to become 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.172 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:894dd1c6:node9:switch_binary --> ON [OnOffType] 2020-04-24 18:50:48.189 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 9: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:48.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY not supported 2020-04-24 18:50:48.192 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured 2020-04-24 18:50:48.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Adding to device queue 2020-04-24 18:50:48.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Added 34207 to queue - size 16 2020-04-24 18:50:48.198 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.200 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.202 [ome.event.ItemCommandEvent] - Item 'BS_Shop_Switch' received command ON 2020-04-24 18:50:48.217 [ome.event.ItemCommandEvent] - Item 'BS_WineCellar_Switch' received command ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:894dd1c6:node2:switch_binary1 --> ON [OnOffType] 2020-04-24 18:50:48.218 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:48.220 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, instance / endpoint 1 2020-04-24 18:50:48.222 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:50:48.223 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2020-04-24 18:50:48.225 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:50:48.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue 2020-04-24 18:50:48.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 34208 to queue - size 17 2020-04-24 18:50:48.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.238 [ome.event.ItemCommandEvent] - Item 'BS_Hallway_Trains_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.240 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:894dd1c6:node11:switch_binary1 --> ON [OnOffType] 2020-04-24 18:50:48.242 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_SET 2020-04-24 18:50:48.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Encapsulating message, instance / endpoint 1 2020-04-24 18:50:48.247 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 11: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1 2020-04-24 18:50:48.249 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: SECURITY not supported 2020-04-24 18:50:48.251 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured 2020-04-24 18:50:48.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue 2020-04-24 18:50:48.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Added 34209 to queue - size 18 2020-04-24 18:50:48.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.261 [ome.event.ItemCommandEvent] - Item 'BS_MainRoom_Pendants_Dimmer1' received command 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.262 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.264 [nt.ItemStatePredictedEvent] - ML_Pantry_Switch predicted to become ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.270 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:894dd1c6:node6:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:48.273 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 6: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:48.274 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY not supported 2020-04-24 18:50:48.276 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.279 [vent.ItemStateChangedEvent] - ML_LivingRoom_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.280 [nt.ItemStatePredictedEvent] - ML_Kitchen_Bar_Lights predicted to become ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.282 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:894dd1c6:node8:switch_dimmer --> 100 [PercentType] 2020-04-24 18:50:48.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue 2020-04-24 18:50:48.285 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 8: Creating new message for command SWITCH_MULTILEVEL_SET 2020-04-24 18:50:48.287 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2020-04-24 18:50:48.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added 34210 to queue - size 19 2020-04-24 18:50:48.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured 2020-04-24 18:50:48.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling initialised at 86400 seconds - start in 1500 milliseconds. 2020-04-24 18:50:48.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue 2020-04-24 18:50:48.295 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Added 34211 to queue - size 20 ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.297 [nt.ItemStatePredictedEvent] - ML_Kitchen_Sconce_Lights predicted to become ON ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:48.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:48.299 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling initialised at 86400 seconds - start in 1500 milliseconds. ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:48.309 [nt.ItemStatePredictedEvent] - ML_Hallway_Dimmer1 predicted to become 100 2020-04-24 18:50:48.322 [nt.ItemStatePredictedEvent] - ML_Hallway_Dimmer2 predicted to become 100 2020-04-24 18:50:48.335 [nt.ItemStatePredictedEvent] - ML_Hallway_Dimmer3 predicted to become 100 2020-04-24 18:50:48.347 [nt.ItemStatePredictedEvent] - ML_Hallway_Dimmer4 predicted to become 100 2020-04-24 18:50:48.360 [nt.ItemStatePredictedEvent] - ML_DiningRoom_Dimmer1 predicted to become 100 2020-04-24 18:50:48.372 [vent.ItemStateChangedEvent] - ML_LivingRoom_Dimmer2 changed from 0 to 100 2020-04-24 18:50:48.374 [nt.ItemStatePredictedEvent] - ML_GameBathroom_Switch predicted to become NULL 2020-04-24 18:50:48.376 [nt.ItemStatePredictedEvent] - ML_PowderRoom_Switch predicted to become ON 2020-04-24 18:50:48.388 [nt.ItemStatePredictedEvent] - ML_MudRoom_Lights predicted to become ON 2020-04-24 18:50:48.399 [nt.ItemStatePredictedEvent] - ML_Garage_Switch predicted to become ON 2020-04-24 18:50:48.411 [nt.ItemStatePredictedEvent] - BS_Hallway_Dimmer1 predicted to become 100 2020-04-24 18:50:48.424 [vent.ItemStateChangedEvent] - ML_Kitchen_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.425 [nt.ItemStatePredictedEvent] - BS_MainRoom_Switch1 predicted to become ON 2020-04-24 18:50:48.438 [vent.ItemStateChangedEvent] - ML_Kitchen_Dimmer2 changed from 0 to 100 2020-04-24 18:50:48.440 [nt.ItemStatePredictedEvent] - BS_Shop_Switch predicted to become ON 2020-04-24 18:50:48.452 [nt.ItemStatePredictedEvent] - BS_WineCellar_Switch predicted to become ON 2020-04-24 18:50:48.462 [nt.ItemStatePredictedEvent] - BS_Hallway_Trains_Dimmer1 predicted to become 100 2020-04-24 18:50:48.479 [nt.ItemStatePredictedEvent] - BS_MainRoom_Pendants_Dimmer1 predicted to become 100 2020-04-24 18:50:48.492 [vent.ItemStateChangedEvent] - ML_Pantry_Switch changed from OFF to ON 2020-04-24 18:50:48.495 [vent.ItemStateChangedEvent] - ML_Kitchen_Bar_Lights changed from OFF to ON 2020-04-24 18:50:48.496 [vent.ItemStateChangedEvent] - ML_Kitchen_Sconce_Lights changed from OFF to ON 2020-04-24 18:50:48.499 [vent.ItemStateChangedEvent] - ML_Hallway_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.501 [vent.ItemStateChangedEvent] - ML_Hallway_Dimmer2 changed from 0 to 100 2020-04-24 18:50:48.503 [vent.ItemStateChangedEvent] - ML_Hallway_Dimmer3 changed from 0 to 100 2020-04-24 18:50:48.505 [vent.ItemStateChangedEvent] - ML_Hallway_Dimmer4 changed from 0 to 100 2020-04-24 18:50:48.507 [vent.ItemStateChangedEvent] - ML_DiningRoom_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.509 [vent.ItemStateChangedEvent] - ML_PowderRoom_Switch changed from OFF to ON 2020-04-24 18:50:48.511 [vent.ItemStateChangedEvent] - ML_MudRoom_Lights changed from OFF to ON 2020-04-24 18:50:48.513 [vent.ItemStateChangedEvent] - ML_Garage_Switch changed from OFF to ON 2020-04-24 18:50:48.515 [vent.ItemStateChangedEvent] - BS_Hallway_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.517 [vent.ItemStateChangedEvent] - BS_MainRoom_Switch1 changed from OFF to ON 2020-04-24 18:50:48.519 [vent.ItemStateChangedEvent] - BS_Shop_Switch changed from OFF to ON 2020-04-24 18:50:48.520 [vent.ItemStateChangedEvent] - BS_WineCellar_Switch changed from OFF to ON 2020-04-24 18:50:48.523 [vent.ItemStateChangedEvent] - BS_Hallway_Trains_Dimmer1 changed from 0 to 100 2020-04-24 18:50:48.524 [vent.ItemStateChangedEvent] - BS_MainRoom_Pendants_Dimmer1 changed from 0 to 100 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:49.328 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling... 2020-04-24 18:50:49.330 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling deferred until initialisation complete 2020-04-24 18:50:49.339 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling... 2020-04-24 18:50:49.341 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling deferred until initialisation complete 2020-04-24 18:50:49.357 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling... 2020-04-24 18:50:49.359 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Polling deferred until initialisation complete 2020-04-24 18:50:49.395 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling... 2020-04-24 18:50:49.397 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling deferred until initialisation complete 2020-04-24 18:50:49.414 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling... 2020-04-24 18:50:49.416 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling deferred until initialisation complete 2020-04-24 18:50:49.448 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling... 2020-04-24 18:50:49.449 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling deferred until initialisation complete 2020-04-24 18:50:49.470 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling... 2020-04-24 18:50:49.473 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete 2020-04-24 18:50:49.490 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling... 2020-04-24 18:50:49.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling deferred until initialisation complete 2020-04-24 18:50:49.511 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling... 2020-04-24 18:50:49.514 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Polling deferred until initialisation complete 2020-04-24 18:50:49.532 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling... 2020-04-24 18:50:49.534 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling deferred until initialisation complete 2020-04-24 18:50:49.548 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Polling... 2020-04-24 18:50:49.550 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: Polling deferred until initialisation complete 2020-04-24 18:50:49.572 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling... 2020-04-24 18:50:49.575 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Polling deferred until initialisation complete 2020-04-24 18:50:49.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling... 2020-04-24 18:50:49.611 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Polling deferred until initialisation complete 2020-04-24 18:50:49.621 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling... 2020-04-24 18:50:49.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling deferred until initialisation complete 2020-04-24 18:50:49.650 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling... 2020-04-24 18:50:49.652 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Polling deferred until initialisation complete 2020-04-24 18:50:49.672 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling... 2020-04-24 18:50:49.674 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling deferred until initialisation complete 2020-04-24 18:50:49.700 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling... 2020-04-24 18:50:49.703 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling deferred until initialisation complete 2020-04-24 18:50:49.731 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling... 2020-04-24 18:50:49.733 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling deferred until initialisation complete 2020-04-24 18:50:49.762 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling... 2020-04-24 18:50:49.766 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling deferred until initialisation complete 2020-04-24 18:50:49.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling... 2020-04-24 18:50:49.795 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Polling deferred until initialisation complete 2020-04-24 18:50:49.799 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling... 2020-04-24 18:50:49.801 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling deferred until initialisation complete 2020-04-24 18:50:49.827 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 27: TID 34191: Timeout at state WAIT_RESPONSE. 3 retries remaining. 2020-04-24 18:50:49.829 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2020-04-24 18:50:49.830 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34191: Transaction ABORTED 2020-04-24 18:50:49.833 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2020-04-24 18:50:49.835 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2020-04-24 18:50:49.837 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2020-04-24 18:50:49.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2020-04-24 18:50:54.106 [DEBUG] [overy.OpenWeatherMapDiscoveryService] - Location is not set -> Will not provide any discovery results. 2020-04-24 18:50:56.727 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:56.764 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 279.9198467102484 to 280.0813624820797 2020-04-24 18:50:56.768 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 8.695059646367993 to 8.51127765851864 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:50:56.968 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:50:56.988 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 268.4796020600549 to 268.6451841519945 2020-04-24 18:50:56.990 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 26.009249558944955 to 25.828951441554352 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:51:00.014 [INFO ] [e.smarthome.model.script.Time of Day] - Calculating time of day... 2020-04-24 18:51:00.115 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated time of day is EVENING1 2020-04-24 18:51:00.122 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated light / dark outside is LIGHT 2020-04-24 18:51:00.133 [INFO ] [e.smarthome.model.script.Time of Day] - Weather_OWM_Temperature 45.59 °F 2020-04-24 18:51:00.143 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature Item NULL 2020-04-24 18:51:00.151 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature State Item NULL ==> /var/log/openhab2/events.log <== 2020-04-24 18:51:00.160 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING1 2020-04-24 18:51:00.165 [ome.event.ItemCommandEvent] - Item 'vLightOutside' received command LIGHT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:51:01.832 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 27: TID 34191: Timeout at state ABORTED. 3 retries remaining. 2020-04-24 18:51:01.834 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 34191: Transaction is current transaction, so clearing!!!!! 2020-04-24 18:51:01.836 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 34191: Transaction CANCELLED 2020-04-24 18:51:01.838 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2020-04-24 18:51:01.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 27: notifyTransactionResponse TID:34191 CANCELLED 2020-04-24 18:51:01.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2020-04-24 18:51:01.844 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1C 03 26 01 63 25 94 0C 2020-04-24 18:51:01.847 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 28: Sending REQUEST Message = 01 0A 00 13 1C 03 26 01 63 25 94 0C 2020-04-24 18:51:10.850 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:51:40.756 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job 2020-04-24 18:51:40.855 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:51:40.860 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed ==> /var/log/openhab2/events.log <== 2020-04-24 18:51:41.179 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2020-04-24T18:50:41.165-0500 to 2020-04-24T18:51:41.168-0500 2020-04-24 18:51:41.184 [vent.ItemStateChangedEvent] - Current_date_time changed from 2020-04-24T18:50:41.165-0500 to 2020-04-24T18:51:41.168-0500 2020-04-24 18:51:41.185 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2020-04-24 18:50:41 CDT to 2020-04-24 18:51:41 CDT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:51:54.107 [DEBUG] [overy.OpenWeatherMapDiscoveryService] - Location is not set -> Will not provide any discovery results. 2020-04-24 18:51:56.732 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:51:56.774 [vent.ItemStateChangedEvent] - Sun_Azimuth changed from 280.0813624820797 to 280.24291592111217 2020-04-24 18:51:56.784 [vent.ItemStateChangedEvent] - Sun_Elevation changed from 8.51127765851864 to 8.3275785804244 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:51:56.968 [DEBUG] [o.internal.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home ==> /var/log/openhab2/events.log <== 2020-04-24 18:51:56.980 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 268.6451841519945 to 268.81048380701657 2020-04-24 18:51:56.987 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 25.828951441554352 to 25.648652571745757 ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:52:00.016 [INFO ] [e.smarthome.model.script.Time of Day] - Calculating time of day... 2020-04-24 18:52:00.117 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated time of day is EVENING1 2020-04-24 18:52:00.121 [INFO ] [e.smarthome.model.script.Time of Day] - Calculated light / dark outside is LIGHT 2020-04-24 18:52:00.128 [INFO ] [e.smarthome.model.script.Time of Day] - Weather_OWM_Temperature 45.59 °F 2020-04-24 18:52:00.132 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature Item NULL 2020-04-24 18:52:00.137 [INFO ] [e.smarthome.model.script.Time of Day] - Outside Temperature State Item NULL ==> /var/log/openhab2/events.log <== 2020-04-24 18:52:00.148 [ome.event.ItemCommandEvent] - Item 'vTimeOfDay' received command EVENING1 2020-04-24 18:52:00.158 [ome.event.ItemCommandEvent] - Item 'vLightOutside' received command LIGHT ==> /var/log/openhab2/openhab.log <== 2020-04-24 18:52:03.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@9a813a 2020-04-24 18:52:04.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@d077b 2020-04-24 18:52:10.858 [DEBUG] [nd.internal.net.SocketChannelSession] - Sending Command: '' 2020-04-24 18:52:12.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@a35949 2020-04-24 18:52:21.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@778d29