Rules to reload on thing changes

Marcin_J · May 3, 2020, 8:43pm

I found interesting correlation about lag problem described at the beginning of this thread (often rules restart/reload and need to wait ~8 seconds).
I add log to System started:
[INFO ] [pse.smarthome.model.script.variables] - Event System started raised

Now I know more precisely when the reload happen. For this test I removed cyclic cron rule to force rules wakeup and be ready for real motion sensor events. So in the logs I can find correlation between System started event and [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED] which belongs to zwave danfoos LC-13 thermostat. Filtered log:

2020-05-03 18:54:50.971 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 18:54:59.743 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 18:59:43.617 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 18:59:52.305 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:04:36.233 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:04:44.733 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:09:28.818 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:09:36.824 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:14:21.409 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:14:29.911 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:19:14.067 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:19:22.784 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:24:06.644 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:24:14.618 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised
2020-05-03 19:28:59.214 [INFO ] [veClimateControlScheduleCommandClass] - NODE 4 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-05-03 19:29:07.700 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised

Further tests give me more facts:

other communication with this device also causes rules restart (when i push middle button on thermostat to wake it up or set something in configuration (paperui/habmin) and save it)
remove battery from this thermostat cause no rules reload takes place

So it looks like there is a problem with configuration of this device. @chris please take look at this.
I use openHab 2.5.4 Release build, updated today. This problem probably didn’t occur in openHab 2.3.

The zwave debug log after wakeup button press:

2020-05-03 22:18:54.950 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 16 00 49 84 18 10 04 08 04 80 46 81 72 8F 75 43 86 84 EF 46 81 8F 0D 
2020-05-03 22:18:54.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=132, payload=84 18 10 04 08 04 80 46 81 72 8F 75 43 86 84 EF 46 81 8F 
2020-05-03 22:18:54.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=132, payload=84 18 10 04 08 04 80 46 81 72 8F 75 43 86 84 EF 46 81 8F 
2020-05-03 22:18:54.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-05-03 22:18:54.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2020-05-03 22:18:54.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2020-05-03 22:18:54.980 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=132, payload=84 18 10 04 08 04 80 46 81 72 8F 75 43 86 84 EF 46 81 8F 
2020-05-03 22:18:54.983 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 24: Application update request. Node information received. Transaction null
2020-05-03 22:18:54.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:54.988 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 24: Application update request. Requesting node state.
2020-05-03 22:18:54.990 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2020-05-03 22:18:54.992 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling initialised at 1800 seconds - start in 175 milliseconds.
2020-05-03 22:18:54.994 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 24: Application update - no transaction.
2020-05-03 22:18:54.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:54.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:55.167 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling...
2020-05-03 22:18:55.169 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling zwave:device:77badcb7:node24:thermostat_setpoint_heating
2020-05-03 22:18:55.171 [DEBUG] [ter.ZWaveThermostatSetpointConverter] - NODE 24: Generating poll message for COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0
2020-05-03 22:18:55.173 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 24: Creating new message for application command THERMOSTAT_SETPOINT_GET (Heating)
2020-05-03 22:18:55.175 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:55.178 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT is NOT required to be secured
2020-05-03 22:18:55.180 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling zwave:device:77badcb7:node24:battery-level
2020-05-03 22:18:55.182 [DEBUG] [rnal.converter.ZWaveBatteryConverter] - NODE 24: Generating poll message for COMMAND_CLASS_BATTERY endpoint 0
2020-05-03 22:18:55.184 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:55.187 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_BATTERY is NOT required to be secured
2020-05-03 22:18:55.189 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling zwave:device:77badcb7:node24:time_offset
2020-05-03 22:18:55.191 [DEBUG] [ternal.converter.ZWaveClockConverter] - NODE 24: Generating poll message for COMMAND_CLASS_CLOCK endpoint 0
2020-05-03 22:18:55.193 [DEBUG] [.commandclass.ZWaveClockCommandClass] - NODE 24: Creating new message for command CLOCK_GET
2020-05-03 22:18:55.195 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:55.197 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_CLOCK is NOT required to be secured
2020-05-03 22:18:55.200 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Polling zwave:device:77badcb7:node24:alarm_general
2020-05-03 22:18:55.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Bump transaction 118 priority from Get to Immediate
2020-05-03 22:18:55.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2020-05-03 22:18:55.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 118 to queue - size 5
2020-05-03 22:18:55.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:55.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Bump transaction 119 priority from Get to Immediate
2020-05-03 22:18:55.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2020-05-03 22:18:55.215 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 119 to queue - size 6
2020-05-03 22:18:55.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:55.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Bump transaction 120 priority from Get to Immediate
2020-05-03 22:18:55.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2020-05-03 22:18:55.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 120 to queue - size 7
2020-05-03 22:18:55.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:55.247 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Is awake with 3 messages in the queue
2020-05-03 22:18:55.249 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Start sleep timer at 1000ms
2020-05-03 22:18:55.251 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2020-05-03 22:18:55.272 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:thermostat_setpoint_heating unlinked - polling stopped.
2020-05-03 22:18:55.277 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:battery-level unlinked - polling stopped.
2020-05-03 22:18:55.292 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:time_offset unlinked - polling stopped.
2020-05-03 22:18:55.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:alarm_general unlinked - polling stopped.
2020-05-03 22:18:55.310 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:thermostat_setpoint_heating linked - polling started.
2020-05-03 22:18:55.318 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:battery-level linked - polling started.
2020-05-03 22:18:55.321 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:time_offset linked - polling started.
2020-05-03 22:18:55.327 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Channel zwave:device:77badcb7:node24:alarm_general linked - polling started.
2020-05-03 22:18:55.333 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 24: Node Status event - Node is AWAKE
2020-05-03 22:18:55.751 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: WakeupTimerTask 3 Messages waiting, state DONE
2020-05-03 22:18:56.252 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: WakeupTimerTask 3 Messages waiting, state DONE
2020-05-03 22:18:56.254 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: No more messages, go back to sleep
2020-05-03 22:18:56.258 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 24: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2020-05-03 22:18:56.260 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:56.264 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2020-05-03 22:18:56.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@16c1154
2020-05-03 22:18:56.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Bump transaction 121 priority from Immediate to Immediate
2020-05-03 22:18:56.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2020-05-03 22:18:56.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 121 to queue - size 8
2020-05-03 22:18:56.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:56.283 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 18 03 43 02 01 25 50 C8 
2020-05-03 22:18:56.287 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 0A 00 13 18 03 43 02 01 25 50 C8 
2020-05-03 22:18:56.290 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-05-03 22:18:56.293 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-05-03 22:18:56.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 118: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 118: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-05-03 22:18:56.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-05-03 22:18:56.312 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-05-03 22:18:56.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 118: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 118: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.337 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.340 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack.
2020-05-03 22:18:56.340 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 50 00 00 02 B9 
2020-05-03 22:18:56.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 118: Advanced to WAIT_REQUEST
2020-05-03 22:18:56.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 118: Transaction not completed
2020-05-03 22:18:56.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=80, payload=50 00 00 02 
2020-05-03 22:18:56.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-05-03 22:18:56.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=80, payload=50 00 00 02 
2020-05-03 22:18:56.359 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 18 06 43 03 01 42 08 34 D6 
2020-05-03 22:18:56.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 118: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 118: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 80
2020-05-03 22:18:56.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 06 43 03 01 42 08 34 
2020-05-03 22:18:56.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 118: (Callback 80)
2020-05-03 22:18:56.367 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-05-03 22:18:56.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 118: callback 80
2020-05-03 22:18:56.371 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=80, payload=50 00 00 02 
2020-05-03 22:18:56.373 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 80, Status = Transmission complete and ACK received(0)
2020-05-03 22:18:56.375 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 118: Advanced to WAIT_DATA
2020-05-03 22:18:56.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 118: Transaction not completed
2020-05-03 22:18:56.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 06 43 03 01 42 08 34 
2020-05-03 22:18:56.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-05-03 22:18:56.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DONE)
2020-05-03 22:18:56.385 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.386 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0
2020-05-03 22:18:56.388 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:56.389 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V1 THERMOSTAT_SETPOINT_REPORT
2020-05-03 22:18:56.391 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 24: Thermostat Setpoint report Scale = 0
2020-05-03 22:18:56.392 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 24: Thermostat Setpoint Value = 21
2020-05-03 22:18:56.394 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 24: Thermostat Setpoint Report, Type Heating (1), value = 21
2020-05-03 22:18:56.395 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
2020-05-03 22:18:56.397 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_THERMOSTAT_SETPOINT, value=21
2020-05-03 22:18:56.399 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Updating channel state zwave:device:77badcb7:node24:thermostat_setpoint_heating to 21 °C [QuantityType]
2020-05-03 22:18:56.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1.
2020-05-03 22:18:56.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18f01fd.
2020-05-03 22:18:56.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18f01fd.
2020-05-03 22:18:56.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:118 DONE
2020-05-03 22:18:56.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-03 22:18:56.415 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-05-03 22:18:56.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-05-03 22:18:56.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:56.425 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 18 02 80 02 25 51 09 
2020-05-03 22:18:56.428 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 09 00 13 18 02 80 02 25 51 09 
2020-05-03 22:18:56.432 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-05-03 22:18:56.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.430 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-05-03 22:18:56.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 119: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.440 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-05-03 22:18:56.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 119: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-05-03 22:18:56.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 119: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.457 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 51 00 00 02 B8 
2020-05-03 22:18:56.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 119: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=81, payload=51 00 00 02 
2020-05-03 22:18:56.461 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.464 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack.
2020-05-03 22:18:56.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 119: Advanced to WAIT_REQUEST
2020-05-03 22:18:56.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 119: Transaction not completed
2020-05-03 22:18:56.469 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 18 03 80 03 30 5A 
2020-05-03 22:18:56.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=81, payload=51 00 00 02 
2020-05-03 22:18:56.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 119: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 03 80 03 30 
2020-05-03 22:18:56.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 119: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 81
2020-05-03 22:18:56.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 119: (Callback 81)
2020-05-03 22:18:56.484 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-05-03 22:18:56.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 119: callback 81
2020-05-03 22:18:56.488 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=81, payload=51 00 00 02 
2020-05-03 22:18:56.490 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 81, Status = Transmission complete and ACK received(0)
2020-05-03 22:18:56.493 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 119: Advanced to WAIT_DATA
2020-05-03 22:18:56.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 119: Transaction not completed
2020-05-03 22:18:56.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 03 80 03 30 
2020-05-03 22:18:56.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-05-03 22:18:56.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DONE)
2020-05-03 22:18:56.502 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.505 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0
2020-05-03 22:18:56.506 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:56.508 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT
2020-05-03 22:18:56.509 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 24: Battery report value = 48
2020-05-03 22:18:56.511 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-05-03 22:18:56.512 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=48
2020-05-03 22:18:56.514 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Updating channel state zwave:device:77badcb7:node24:battery-level to 48 [DecimalType]
2020-05-03 22:18:56.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1.
2020-05-03 22:18:56.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@37071d.
2020-05-03 22:18:56.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@37071d.
2020-05-03 22:18:56.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:119 DONE
2020-05-03 22:18:56.527 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-03 22:18:56.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-05-03 22:18:56.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-05-03 22:18:56.532 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:56.536 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 18 02 81 05 25 52 0C 
2020-05-03 22:18:56.538 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 09 00 13 18 02 81 05 25 52 0C 
2020-05-03 22:18:56.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-05-03 22:18:56.543 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-05-03 22:18:56.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.552 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-05-03 22:18:56.556 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 120: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 120: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-05-03 22:18:56.567 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 52 00 00 02 BB 
2020-05-03 22:18:56.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 120: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=82, payload=52 00 00 02 
2020-05-03 22:18:56.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 120: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.579 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.579 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 18 04 81 06 F6 12 8E 
2020-05-03 22:18:56.581 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack.
2020-05-03 22:18:56.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 120: Advanced to WAIT_REQUEST
2020-05-03 22:18:56.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 04 81 06 F6 12 
2020-05-03 22:18:56.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 120: Transaction not completed
2020-05-03 22:18:56.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=SendData[19], type=Request[0], dest=0, callback=82, payload=52 00 00 02 
2020-05-03 22:18:56.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 120: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 120: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 82
2020-05-03 22:18:56.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 120: (Callback 82)
2020-05-03 22:18:56.596 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-05-03 22:18:56.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 120: callback 82
2020-05-03 22:18:56.599 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=82, payload=52 00 00 02 
2020-05-03 22:18:56.601 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 82, Status = Transmission complete and ACK received(0)
2020-05-03 22:18:56.603 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 120: Advanced to WAIT_DATA
2020-05-03 22:18:56.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 120: Transaction not completed
2020-05-03 22:18:56.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=24, callback=0, payload=00 18 04 81 06 F6 12 
2020-05-03 22:18:56.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-05-03 22:18:56.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Application Command Request (ALIVE:DONE)
2020-05-03 22:18:56.613 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.615 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Incoming command class COMMAND_CLASS_CLOCK, endpoint 0
2020-05-03 22:18:56.616 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: SECURITY not supported
2020-05-03 22:18:56.618 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 24: Received COMMAND_CLASS_CLOCK V1 CLOCK_REPORT
2020-05-03 22:18:56.619 [DEBUG] [.commandclass.ZWaveClockCommandClass] - NODE 24: Received clock report: niedziela 22:18
2020-05-03 22:18:56.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-05-03 22:18:56.623 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_CLOCK, value=Sun May 03 22:18:56 CEST 2020
2020-05-03 22:18:56.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Updating channel state zwave:device:77badcb7:node24:time_offset to 0 [DecimalType]
2020-05-03 22:18:56.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Commands processed 1.
2020-05-03 22:18:56.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2bc774.
2020-05-03 22:18:56.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2bc774.
2020-05-03 22:18:56.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:120 DONE
2020-05-03 22:18:56.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-03 22:18:56.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-05-03 22:18:56.639 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-05-03 22:18:56.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:18:56.644 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 18 02 84 08 25 53 05 
2020-05-03 22:18:56.647 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 24: Sending REQUEST Message = 01 09 00 13 18 02 84 08 25 53 05 
2020-05-03 22:18:56.648 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-05-03 22:18:56.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 121: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.651 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-05-03 22:18:56.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-05-03 22:18:56.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.659 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-05-03 22:18:56.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-05-03 22:18:56.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.675 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 53 00 00 03 BB 
2020-05-03 22:18:56.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-05-03 22:18:56.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=83, payload=53 00 00 03 
2020-05-03 22:18:56.685 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: sentData successfully placed on stack.
2020-05-03 22:18:56.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 121: Advanced to WAIT_REQUEST
2020-05-03 22:18:56.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 121: Transaction not completed
2020-05-03 22:18:56.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=83, payload=53 00 00 03 
2020-05-03 22:18:56.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-05-03 22:18:56.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 83
2020-05-03 22:18:56.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 121: (Callback 83)
2020-05-03 22:18:56.700 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-05-03 22:18:56.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 121: callback 83
2020-05-03 22:18:56.704 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=83, payload=53 00 00 03 
2020-05-03 22:18:56.706 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 24: SendData Request. CallBack ID = 83, Status = Transmission complete and ACK received(0)
2020-05-03 22:18:56.708 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: resetResendCount initComplete=true isDead=false
2020-05-03 22:18:56.710 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: Transaction COMPLETED
2020-05-03 22:18:56.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Response processed after 61ms
2020-05-03 22:18:56.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: TID 121: Transaction completed
2020-05-03 22:18:56.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:121 DONE
2020-05-03 22:18:56.716 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-05-03 22:18:56.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 121: Transaction event listener: DONE: DONE -> 
2020-05-03 22:18:56.718 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 24: Went to sleep COMPLETE
2020-05-03 22:18:56.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-05-03 22:18:56.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-05-03 22:19:03.324 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised

chris · May 3, 2020, 8:58pm

Please can you explain what the problem is. I don’t see any issue here - the binding sends all data to the device and receives the response with relatively short time - under 2 seconds. I’m not familiar with the script event log you are logging, but I don’t think it’s linked to the binding?

rossko57 · May 3, 2020, 9:18pm

Look also for Thing updates at this time in your log

Marcin_J · May 3, 2020, 10:00pm

Simply - the problem is that after communication with one particular z-wave device all rules reload, and system event “System started” raises. This cause lag in starting other rules and other problems like reset of my “Enable_Home_Automation” variable.

This is the rule which log is present at the end of second log from my previous post:

var Timer timerStartup = null

rule SetSystemStartedVariable
when
  System started
then
  logInfo("variables", "Event System started raised")

  SystemStartedDateTime.sendCommand(new DateTimeType())

  SystemStarting.postUpdate(ON)

  timerStartup = createTimer(now.plusSeconds(15), [|
    SystemStarting.postUpdate(OFF)
    timerStartup.cancel()
    timerStartup = null
  ])

  Enable_Home_Automation.sendCommand(ON)
end

Additional event.log as @rossko57 ask (mainly from 18:54 to not spam to much):

2020-05-03 18:54:24.650 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 518 to 519
2020-05-03 18:54:24.668 [vent.ItemStateChangedEvent] - Bedroom_MotionSensor_Luminance changed from 10 to 8
2020-05-03 18:54:35.632 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 519 to 520
2020-05-03 18:54:35.666 [vent.ItemStateChangedEvent] - Bathroom_Temperature changed from 22.2 to 22.38
2020-05-03 18:54:35.677 [GroupItemStateChangedEvent] - gTemperature changed from 22.02 to 22.08 through Bathroom_Temperature
2020-05-03 18:54:45.885 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_latency changed from 19.0 to 18.0
2020-05-03 18:54:47.208 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_lastseen changed from 2020-05-03T18:53:45.822+0200 to 2020-05-03T18:54:47.182+0200
2020-05-03 18:54:48.251 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_13_latency changed from 17.0 to 23.0
2020-05-03 18:54:49.576 [vent.ItemStateChangedEvent] - network_pingdevice_d9b62db7_lastseen changed from 2020-05-03T18:53:48.162+0200 to 2020-05-03T18:54:49.552+0200
2020-05-03 18:54:49.621 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_13_lastseen changed from 2020-05-03T18:53:48.193+0200 to 2020-05-03T18:54:49.602+0200
2020-05-03 18:54:50.924 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 520 to 521
2020-05-03 18:54:50.933 [vent.ItemStateChangedEvent] - zwave_device_77badcb7_node4_battery_level changed from NULL to 43
2020-05-03 18:54:50.943 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 521 to 522
2020-05-03 18:54:50.962 [vent.ItemStateChangedEvent] - zwave_device_77badcb7_node4_thermostat_setpoint_heating changed from NULL to 22 °C
2020-05-03 18:54:50.972 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 522 to 523
2020-05-03 18:54:50.984 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 523 to 524
2020-05-03 18:54:51.052 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:77badcb7:node4' has been updated.
2020-05-03 18:54:51.994 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_ack changed from 85 to 86
2020-05-03 18:54:51.999 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 524 to 525
2020-05-03 18:54:52.016 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 525 to 526
2020-05-03 18:54:54.107 [vent.ItemStateChangedEvent] - network_pingdevice_915dda31_latency changed from 281.0 to 780.0
2020-05-03 18:54:54.653 [vent.ItemStateChangedEvent] - network_pingdevice_915dda31_lastseen changed from 2020-05-03T18:53:52.159+0200 to 2020-05-03T18:54:54.098+0200
2020-05-03 18:54:59.170 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 526 to 527
2020-05-03 18:54:59.181 [vent.ItemStateChangedEvent] - Kitchen_MotionSensor_Luminance changed from 24 to 21
2020-05-03 18:54:59.756 [vent.ItemStateChangedEvent] - SystemStartedDateTime changed from 2020-05-03T18:50:41.606+0200 to 2020-05-03T18:54:59.746+0200
2020-05-03 18:54:59.761 [vent.ItemStateChangedEvent] - SystemStarting changed from OFF to ON
2020-05-03 18:55:02.201 [vent.ItemStateChangedEvent] - zwave_serial_zstick_77badcb7_serial_sof changed from 527 to 528
2020-05-03 18:55:02.211 [GroupItemStateChangedEvent] - gTemperature changed from 22.08 to 22.11 through Bedroom_Temperature
2020-05-03 18:55:02.220 [vent.ItemStateChangedEvent] - Bedroom_Temperature changed from 22.11 to 22.2
2020-05-03 18:55:14.765 [vent.ItemStateChangedEvent] - SystemStarting changed from ON to OFF
2020-05-03 18:55:25.207 [vent.ItemStateChangedEvent] - raspberryTempString changed from temp=56.9'C to temp=58.0'C
2020-05-03 18:55:47.246 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_latency changed from 18.0 to 20.0
2020-05-03 18:55:48.560 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_lastseen changed from 2020-05-03T18:54:47.182+0200 to 2020-05-03T18:55:48.532+0200
2020-05-03 18:55:49.657 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_13_latency changed from 23.0 to 19.0
2020-05-03 18:55:50.975 [vent.ItemStateChangedEvent] - network_pingdevice_d9b62db7_lastseen changed from 2020-05-03T18:54:49.552+0200 to 2020-05-03T18:55:50.961+0200
2020-05-03 18:55:51.010 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_13_lastseen changed from 2020-05-03T18:54:49.602+0200 to 2020-05-03T18:55:50.982+0200
2020-05-03 18:55:55.347 [vent.ItemStateChangedEvent] - network_pingdevice_915dda31_latency changed from 780.0 to 683.0
2020-05-03 18:55:56.036 [vent.ItemStateChangedEvent] - network_pingdevice_915dda31_lastseen changed from 2020-05-03T18:54:54.098+0200 to 2020-05-03T18:55:55.331+0200
2020-05-03 18:56:48.588 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_latency changed from 20.0 to 16.0
2020-05-03 18:56:49.933 [vent.ItemStateChangedEvent] - network_pingdevice_192_168_0_25_lastseen changed from 2020-05-03T18:55

chris · May 3, 2020, 10:02pm

I’m not aware of any way that the binding can cause the rules etc to reload so I’m not really sure how the binding can do this.

Marcin_J · May 3, 2020, 10:12pm

I suspect an error which could crash rules engine… I’m not familiar with the source code so I can only guess. Maybe any sugestion of which else log can I enable to DEBUG to see more?

Communication is:
Thermostat ↔ z-wave controller (aeotec) ↔ z-wave binding

What else can cause this problem? Aeotec dongle itself?
But as I said, change configuration field in the z-wave thing configuration page also causes this problem so probably not the communication itself (if I understand correctly, this device need to wake up to get this updated value)?
I tried to change this value:

chris · May 3, 2020, 10:14pm

I’ve no idea - as I said, I don’t think that this can be an issue in the binding. There have been very few changes in the binding in recent times, and the binding shouldn’t be able to impact the rules - but then I know nothing about the rules.

I don’t think that device parameters such as associations will be in any way linked to this.

rossko57 · May 3, 2020, 10:37pm

I think that is the cause of openHAB upheaval.
This is not a status update, like ONLINE/OFFLINE, it is some change of Thing properties, rather like an edit.

In the case of an actual edit, you would want the binding to reinitialize in some way. Many bindings were never very good at accepting in-flight edits.
I believe some changes have been made in this area with 2.5, and it seems to have swung the other way, firing system started (unwanted?)

Now, why a “bad communication” could lead to a Thing update is another story, I have no idea.

Marcin_J · May 3, 2020, 11:13pm

I discovered that it’s not just System starting raise, but all rule files are refreshed:

2020-05-04 01:01:37.018 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'variables.rules'
2020-05-04 01:01:37.188 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'ir.rules'
2020-05-04 01:01:37.374 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'inmate_presence.rules'
2020-05-04 01:01:37.523 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'heating.rules'
2020-05-04 01:01:37.663 [DEBUG] [el.core.internal.ModelRepositoryImpl] - Refreshing resource 'pir.rules'
2020-05-04 01:01:42.971 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing startup rule 'SetSystemStartedVariable'
2020-05-04 01:01:43.095 [INFO ] [pse.smarthome.model.script.variables] - Event System started raised

This method is called probably https://github.com/openhab/openhab-core/blob/61e17ce39e83daa7f1d8c41512dead8d95d6e5d9/bundles/org.openhab.core.model.core/src/main/java/org/openhab/core/model/core/internal/ModelRepositoryImpl.java#L192
called probably by
https://github.com/openhab/openhab-core/blob/3811cb95604f69f6a3d77da2caf391d81b05458e/bundles/org.openhab.core.model.rule/src/org/openhab/core/model/rule/jvmmodel/RulesRefresher.java#L71

So your explanation souns sensible. I’ll try to investigate what can cause the thing update…

mstormi · May 4, 2020, 10:35am

Please don’t invade other threads, I’ve put your posts into this separate one.

Rules to reload are a known issue see also https://github.com/openhab/openhab-core/issues/1365 .

Marcin_J · May 4, 2020, 11:23am

That’s a good reaction but with wrong posts. I created this thread 8 seconds lag always after few minutes without script activation and wanted to continue topic started there with new discoveries… I think that thread split should be between 29 post of ewrw user and 54 + 64 post, because it’s about different case.

mstormi · May 4, 2020, 11:32am

You’re right sorry I missed that. I’ve moved @ewrw’s posts+replies to this separate thread, too.
Let’s keep your new ones separate, too, as focus shifted from the OP.

Marcin_J · May 4, 2020, 11:35am

Thank you. It is possible to join posts from this thread back?
EDIT: Ok I missed the second sentence. Thanks for the github link.

rossko57 · May 4, 2020, 10:58am

Comment: what’s been moved from this thread is about unexpected firing of “system started”, in turn caused by refreshing of rules files.

Note that any in-flight rule file refresh will lead to the “known” effect of a delayed first-time rule run, there is a link to the symptoms here but not the root cause.