==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.411 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to UNINITIALIZED ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.446 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Handler disposed. Unregistering listener. 2019-09-22 12:24:21.466 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=442, service.bundleid=244, service.scope=singleton} - org.openhab.binding.zwave ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.475 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.505 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=443, service.bundleid=244, service.scope=singleton} - org.openhab.binding.zwave ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.525 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.547 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:f5074b06:node12. 2019-09-22 12:24:21.551 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to ONLINE. 2019-09-22 12:24:21.552 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is ONLINE. Starting device initialisation. ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.553 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline 2019-09-22 12:24:21.570 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.594 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.600 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=881 2019-09-22 12:24:21.606 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=881. SET. Was 881 2019-09-22 12:24:21.608 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Properties synchronised ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.613 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.620 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration synchronised ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.623 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.631 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added. 2019-09-22 12:24:21.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising Thing Node... 2019-09-22 12:24:21.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:f5074b06:node12:sensor_temperature for QuantityType ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.635 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.637 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:f5074b06:node12:sensor_temperature for QuantityType 2019-09-22 12:24:21.639 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:f5074b06:node12:sensor_luminance for DecimalType ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.641 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]] ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:21.641 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:f5074b06:node12:sensor_luminance for DecimalType 2019-09-22 12:24:21.643 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:f5074b06:node12:alarm_motion for OnOffType 2019-09-22 12:24:21.645 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:f5074b06:node12:alarm_motion for OnOffType 2019-09-22 12:24:21.647 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:f5074b06:node12:battery-level for PercentType 2019-09-22 12:24:21.649 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:f5074b06:node12:battery-level for PercentType 2019-09-22 12:24:21.651 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 1800 seconds - start in 1542600 milliseconds. 2019-09-22 12:24:21.653 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Device initialisation complete. ==> /var/log/openhab2/events.log <== 2019-09-22 12:24:21.660 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:24:30.915 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:f5074b06 2019-09-22 12:24:30.919 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do 2019-09-22 12:25:38.172 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update received 2019-09-22 12:25:38.190 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_30_2 to 0 (BigDecimal) 2019-09-22 12:25:38.192 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_31_2 to 0 (BigDecimal) 2019-09-22 12:25:38.195 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set binding_cmdrepollperiod to 1500 (BigDecimal) 2019-09-22 12:25:38.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_11_1 to 2 (BigDecimal) 2019-09-22 12:25:38.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_10_1 to 1 (BigDecimal) 2019-09-22 12:25:38.201 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored group_1 to null (null) 2019-09-22 12:25:38.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored group_3 to null (null) 2019-09-22 12:25:38.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored group_2 to null (null) 2019-09-22 12:25:38.208 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set wakeup_node to null (null) 2019-09-22 12:25:38.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Error converting wakeup value null 2019-09-22 12:25:38.213 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_12_1 to 0 (BigDecimal) 2019-09-22 12:25:38.216 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_13_1 to 0 (BigDecimal) 2019-09-22 12:25:38.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_15_1 to 0 (BigDecimal) 2019-09-22 12:25:38.225 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_20_1 to 0 (BigDecimal) 2019-09-22 12:25:38.229 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_21_2 to 25 (BigDecimal) 2019-09-22 12:25:38.231 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set action_failed to false (Boolean) 2019-09-22 12:25:38.234 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set wakeup_interval to 3600 (BigDecimal) 2019-09-22 12:25:38.237 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Set wakeup interval to '3600' 2019-09-22 12:25:38.240 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set action_remove to false (Boolean) 2019-09-22 12:25:38.243 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set binding_pollperiod to 86400 (BigDecimal) 2019-09-22 12:25:38.247 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 86400 seconds - start in 25401600 milliseconds. 2019-09-22 12:25:38.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set action_heal to false (Boolean) 2019-09-22 12:25:38.253 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_1_2 to 30 (BigDecimal) 2019-09-22 12:25:38.255 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_100_2 to 1024 (BigDecimal) 2019-09-22 12:25:38.259 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_7_2 to 239 (BigDecimal) 2019-09-22 12:25:38.261 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_2_2 to 240 (BigDecimal) 2019-09-22 12:25:38.264 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_3_1 to 11 (BigDecimal) 2019-09-22 12:25:38.267 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_22_2 to 100 (BigDecimal) 2019-09-22 12:25:38.270 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_4_1 to 0 (BigDecimal) 2019-09-22 12:25:38.272 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_23_2 to 3600 (BigDecimal) 2019-09-22 12:25:38.275 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_5_1 to 3 (BigDecimal) 2019-09-22 12:25:38.277 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_24_2 to 3600 (BigDecimal) 2019-09-22 12:25:38.280 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored node_id to 12 (BigDecimal) 2019-09-22 12:25:38.283 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update ignored config_6_1 to 0 (BigDecimal) 2019-09-22 12:25:38.293 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Wakeup node not specified, using 1 ==> /var/log/openhab2/events.log <== 2019-09-22 12:25:38.296 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:25:38.296 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 12: Creating new message for command WAKE_UP_INTERVAL_SET to 3600s, node 1 ==> /var/log/openhab2/events.log <== 2019-09-22 12:25:38.300 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=wakeup_interval, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]] ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:25:38.299 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_WAKE_UP 2019-09-22 12:25:38.317 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured 2019-09-22 12:25:38.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 460 priority from Config to Immediate 2019-09-22 12:25:38.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:25:38.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 460 to queue - size 15 2019-09-22 12:25:38.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:25:38.344 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 12: Creating new message for application command WAKE_UP_INTERVAL_GET 2019-09-22 12:25:38.347 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_WAKE_UP 2019-09-22 12:25:38.349 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured 2019-09-22 12:25:38.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 461 priority from Config to Immediate 2019-09-22 12:25:38.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:25:38.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 461 to queue - size 16 2019-09-22 12:25:38.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:26:08.189 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 05 0A 60 0D 01 01 31 05 04 22 00 EA 71 2019-09-22 12:26:08.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 00 EA 2019-09-22 12:26:08.198 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 00 EA 2019-09-22 12:26:08.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:26:08.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:26:08.204 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:26:08.206 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:26:08.208 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1 2019-09-22 12:26:08.210 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL 2019-09-22 12:26:08.211 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 2019-09-22 12:26:08.213 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Type = Power(4), Scale = 0 2019-09-22 12:26:08.215 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Value = 23.4 2019-09-22 12:26:08.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2019-09-22 12:26:08.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=23.4 2019-09-22 12:26:08.222 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 5: Sensor conversion not performed for POWER. 2019-09-22 12:26:08.223 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:sensor_power1 to 23.4 [DecimalType] 2019-09-22 12:26:08.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:26:08.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@905ead. 2019-09-22 12:26:08.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:26:08.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:26:08.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:26:08.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:26:08.566 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 05 07 60 0D 01 01 26 03 63 DF 2019-09-22 12:26:08.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 07 60 0D 01 01 26 03 63 2019-09-22 12:26:08.572 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 07 60 0D 01 01 26 03 63 2019-09-22 12:26:08.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:26:08.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:26:08.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:26:08.579 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:26:08.581 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1 2019-09-22 12:26:08.583 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL 2019-09-22 12:26:08.584 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT 2019-09-22 12:26:08.586 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Switch Multi Level report, value = 99 2019-09-22 12:26:08.588 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2019-09-22 12:26:08.590 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=99 2019-09-22 12:26:08.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:switch_dimmer1 to 100 [PercentType] 2019-09-22 12:26:08.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:26:08.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1447f5e. 2019-09-22 12:26:08.603 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:26:08.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 ==> /var/log/openhab2/events.log <== 2019-09-22 12:26:08.613 [vent.ItemStateChangedEvent] - HallDimmer changed from 0 to 100 ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:26:08.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:26:08.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:26:14.183 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 05 0A 60 0D 01 01 31 05 04 22 04 E5 7A 2019-09-22 12:26:14.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 04 E5 2019-09-22 12:26:14.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 04 E5 2019-09-22 12:26:14.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:26:14.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:26:14.197 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:26:14.199 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:26:14.201 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1 2019-09-22 12:26:14.203 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL 2019-09-22 12:26:14.205 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 2019-09-22 12:26:14.207 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Type = Power(4), Scale = 0 2019-09-22 12:26:14.210 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Value = 125.3 2019-09-22 12:26:14.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2019-09-22 12:26:14.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=125.3 2019-09-22 12:26:14.217 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 5: Sensor conversion not performed for POWER. 2019-09-22 12:26:14.219 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:sensor_power1 to 125.3 [DecimalType] 2019-09-22 12:26:14.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:26:14.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4925c2. 2019-09-22 12:26:14.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:26:14.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:26:14.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:26:14.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:26:57.960 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 49 84 0C 16 04 07 01 5E 98 9F 55 86 73 85 8E 59 72 5A 80 84 30 71 31 70 6C 7A A7 2019-09-22 12:26:57.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=12, callback=132, payload=84 0C 16 04 07 01 5E 98 9F 55 86 73 85 8E 59 72 5A 80 84 30 71 31 70 6C 7A 2019-09-22 12:26:57.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=12, callback=132, payload=84 0C 16 04 07 01 5E 98 9F 55 86 73 85 8E 59 72 5A 80 84 30 71 31 70 6C 7A 2019-09-22 12:26:57.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:26:57.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0 2019-09-22 12:26:57.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null 2019-09-22 12:26:57.974 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=12, callback=132, payload=84 0C 16 04 07 01 5E 98 9F 55 86 73 85 8E 59 72 5A 80 84 30 71 31 70 6C 7A 2019-09-22 12:26:57.975 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update request. Node information received. Transaction null 2019-09-22 12:26:57.977 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Unsupported command class COMMAND_CLASS_SECURITY_2 2019-09-22 12:26:57.978 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE 2019-09-22 12:26:57.980 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Unsupported command class COMMAND_CLASS_SUPERVISION 2019-09-22 12:26:57.982 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 12: Application update - no transaction. 2019-09-22 12:26:57.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:26:57.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:26:58.234 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Is awake with 3 messages in the queue 2019-09-22 12:26:58.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Start sleep timer at 5000ms 2019-09-22 12:26:58.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent 2019-09-22 12:26:58.254 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is AWAKE ==> /var/log/openhab2/events.log <== 2019-09-22 12:26:58.258 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node12' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:27:00.740 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 3 Messages waiting, state VERSION 2019-09-22 12:27:01.737 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 08 03 80 03 63 19 2019-09-22 12:27:01.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 03 80 03 63 2019-09-22 12:27:01.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 03 80 03 63 2019-09-22 12:27:01.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:01.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:01.753 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:01.755 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Incoming command class COMMAND_CLASS_BATTERY, endpoint 0 2019-09-22 12:27:01.759 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 08 06 43 03 01 42 08 34 C6 2019-09-22 12:27:01.761 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2019-09-22 12:27:01.763 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Received COMMAND_CLASS_BATTERY V1 BATTERY_REPORT 2019-09-22 12:27:01.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 06 43 03 01 42 08 34 2019-09-22 12:27:01.765 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 8: Battery report value = 99 2019-09-22 12:27:01.767 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2019-09-22 12:27:01.771 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BATTERY, value=99 2019-09-22 12:27:01.773 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Updating channel state zwave:device:f5074b06:node8:battery-level to 99 [DecimalType] 2019-09-22 12:27:01.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Commands processed 1. 2019-09-22 12:27:01.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@159cef9. 2019-09-22 12:27:01.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.779 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 08 04 46 08 00 7F CC 2019-09-22 12:27:01.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 04 46 08 00 7F 2019-09-22 12:27:01.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 06 43 03 01 42 08 34 2019-09-22 12:27:01.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:01.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:01.789 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:01.791 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Incoming command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0 2019-09-22 12:27:01.793 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2019-09-22 12:27:01.795 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Received COMMAND_CLASS_THERMOSTAT_SETPOINT V1 THERMOSTAT_SETPOINT_REPORT 2019-09-22 12:27:01.797 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 8: Thermostat Setpoint report Scale = 0 2019-09-22 12:27:01.799 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 08 02 84 07 7A 2019-09-22 12:27:01.799 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 8: Thermostat Setpoint Value = 21 2019-09-22 12:27:01.801 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 8: Thermostat Setpoint Report, Type Heating (1), value = 21 2019-09-22 12:27:01.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 02 84 07 2019-09-22 12:27:01.803 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent 2019-09-22 12:27:01.805 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_THERMOSTAT_SETPOINT, value=21 2019-09-22 12:27:01.808 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Updating channel state zwave:device:f5074b06:node8:thermostat_setpoint_heating to 21 °C [QuantityType] 2019-09-22 12:27:01.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Commands processed 1. 2019-09-22 12:27:01.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@d24d7f. 2019-09-22 12:27:01.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 04 46 08 00 7F 2019-09-22 12:27:01.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:01.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:01.825 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:01.827 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Incoming command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE, endpoint 0 2019-09-22 12:27:01.829 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2019-09-22 12:27:01.832 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 8: Received COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE V1 SCHEDULE_OVERRIDE_REPORT 2019-09-22 12:27:01.834 [INFO ] [veClimateControlScheduleCommandClass] - NODE 8 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED] 2019-09-22 12:27:01.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Commands processed 1. 2019-09-22 12:27:01.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@13e5a98. 2019-09-22 12:27:01.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=8, callback=0, payload=00 08 02 84 07 2019-09-22 12:27:01.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:01.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:01.850 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:01.852 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Is awake with 0 messages in the queue 2019-09-22 12:27:01.854 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Start sleep timer at 1000ms 2019-09-22 12:27:01.856 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveNodeStatusEvent ==> /var/log/openhab2/events.log <== 2019-09-22 12:27:01.872 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f5074b06:node8' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:27:01.871 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 8: Node Status event - Node is AWAKE 2019-09-22 12:27:01.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Commands processed 1. 2019-09-22 12:27:01.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b37b36. 2019-09-22 12:27:01.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:01.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:01.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:27:01.884 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 86 13 8E 25 6A BD 2019-09-22 12:27:01.888 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 86 13 8E 25 6A BD 2019-09-22 12:27:01.890 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:01.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 459: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:01.894 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:01.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:01.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:01.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 459: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:01.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:01.900 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2019-09-22 12:27:01.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:01.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:01.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:01.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:01.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 459: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:01.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:01.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 459: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:01.917 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:01.919 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack. 2019-09-22 12:27:01.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 459: Advanced to WAIT_REQUEST 2019-09-22 12:27:01.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 459: Transaction not completed 2019-09-22 12:27:01.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:01.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:02.357 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: WakeupTimerTask 0 Messages waiting, state DONE 2019-09-22 12:27:02.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: WakeupTimerTask 0 Messages waiting, state DONE 2019-09-22 12:27:02.858 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: No more messages, go back to sleep 2019-09-22 12:27:02.861 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 8: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2019-09-22 12:27:02.862 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY not supported 2019-09-22 12:27:02.864 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured 2019-09-22 12:27:02.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1f30328 2019-09-22 12:27:02.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Bump transaction 462 priority from Immediate to Immediate 2019-09-22 12:27:02.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue 2019-09-22 12:27:02.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Added 462 to queue - size 16 2019-09-22 12:27:02.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:03.240 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: WakeupTimerTask 3 Messages waiting, state VERSION 2019-09-22 12:27:03.241 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: No more messages, go back to sleep 2019-09-22 12:27:03.243 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 12: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2019-09-22 12:27:03.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_WAKE_UP 2019-09-22 12:27:03.246 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured 2019-09-22 12:27:03.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@bfb19f 2019-09-22 12:27:03.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 463 priority from Immediate to Immediate 2019-09-22 12:27:03.254 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:27:03.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 463 to queue - size 17 2019-09-22 12:27:03.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:05.693 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6A 00 01 7C FC 2019-09-22 12:27:05.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 01 7C 2019-09-22 12:27:05.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 01 7C 2019-09-22 12:27:05.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 459: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:05.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:05.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 459: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 106 2019-09-22 12:27:05.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 459: (Callback 106) 2019-09-22 12:27:05.708 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2019-09-22 12:27:05.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 459: callback 106 2019-09-22 12:27:05.711 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=106, payload=6A 00 01 7C 2019-09-22 12:27:05.712 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 0C 04 86 14 8E 03 E6 2019-09-22 12:27:05.713 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 106, Status = Transmission complete and ACK received(0) 2019-09-22 12:27:05.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 459: Advanced to WAIT_DATA 2019-09-22 12:27:05.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 459: Transaction not completed 2019-09-22 12:27:05.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 04 86 14 8E 03 2019-09-22 12:27:05.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:05.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:05.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 04 86 14 8E 03 2019-09-22 12:27:05.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:05.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:VERSION) 2019-09-22 12:27:05.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_VERSION, endpoint 0 2019-09-22 12:27:05.734 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_VERSION 2019-09-22 12:27:05.735 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_VERSION V0 VERSION_COMMAND_CLASS_REPORT 2019-09-22 12:27:05.738 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 12: Process Version Command Class Report 2019-09-22 12:27:05.740 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 12: Requested Command Class = COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, Version = 3 2019-09-22 12:27:06.001 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 02 03 20 01 00 D2 2019-09-22 12:27:07.222 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Version = 3, version set. Enabling extra functionality. 2019-09-22 12:27:07.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1. 2019-09-22 12:27:07.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@34467f. 2019-09-22 12:27:07.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@34467f. 2019-09-22 12:27:07.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 20 01 00 2019-09-22 12:27:07.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:459 DONE 2019-09-22 12:27:07.232 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2019-09-22 12:27:07.233 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 02 0A 71 05 00 00 00 FF 07 00 00 00 6F 2019-09-22 12:27:07.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 459: Transaction event listener: DONE: DONE -> 2019-09-22 12:27:07.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:07.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:07.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 03 20 01 00 2019-09-22 12:27:07.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d5f23 2019-09-22 12:27:07.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:07.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:07.240 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node Init transaction completed with response COMPLETE 2019-09-22 12:27:07.243 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:07.245 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: VERSION - checking COMMAND_CLASS_BASIC, version is 0 2019-09-22 12:27:07.246 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_BASIC, endpoint 0 2019-09-22 12:27:07.249 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2019-09-22 12:27:07.249 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: VERSION - queued COMMAND_CLASS_BASIC 2019-09-22 12:27:07.251 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_BASIC V1 BASIC_SET 2019-09-22 12:27:07.253 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 2: Basic report, value = 0 2019-09-22 12:27:07.255 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 12: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_BASIC 2019-09-22 12:27:07.256 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2019-09-22 12:27:07.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 71 05 00 00 00 FF 07 00 00 00 2019-09-22 12:27:07.261 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0 2019-09-22 12:27:07.260 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: ZWaveCommandClassTransactionPayload - send to node 2019-09-22 12:27:07.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2019-09-22 12:27:07.263 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_VERSION 2019-09-22 12:27:07.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@db4a33. 2019-09-22 12:27:07.268 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_VERSION is NOT required to be secured 2019-09-22 12:27:07.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:07.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0 2019-09-22 12:27:07.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1681155 2019-09-22 12:27:07.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0A 71 05 00 00 00 FF 07 00 00 00 2019-09-22 12:27:07.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null 2019-09-22 12:27:07.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Bump transaction 464 priority from Config to Immediate 2019-09-22 12:27:07.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:07.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:27:07.290 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:07.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 464 to queue - size 18 2019-09-22 12:27:07.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:27:07.293 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_ALARM, endpoint 0 2019-09-22 12:27:07.296 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported 2019-09-22 12:27:07.297 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6B 3A 2019-09-22 12:27:07.299 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_ALARM V3 NOTIFICATION_REPORT 2019-09-22 12:27:07.300 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6B 3A 2019-09-22 12:27:07.303 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:07.303 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: NOTIFICATION report - 0 = 0, event=0, status=255, plen=0 2019-09-22 12:27:07.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:07.306 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:07.308 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 2: Alarm Type = BURGLAR (0) 2019-09-22 12:27:07.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:07.311 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveAlarmValueEvent 2019-09-22 12:27:07.316 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2019-09-22 12:27:07.313 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ALARM, value=255 2019-09-22 12:27:07.320 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 2: Alarm converter processing NOTIFICATION 2019-09-22 12:27:07.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:07.322 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 2: Alarm converter NOTIFICATION event is 0, type OnOffType 2019-09-22 12:27:07.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:f5074b06:node2:alarm_motion to OFF [OnOffType] 2019-09-22 12:27:07.326 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 2: Alarm converter processing NOTIFICATION 2019-09-22 12:27:07.327 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 2: Alarm converter NOTIFICATION event is 0, type OnOffType 2019-09-22 12:27:07.329 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:f5074b06:node2:alarm_tamper to OFF [OnOffType] 2019-09-22 12:27:07.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1. 2019-09-22 12:27:07.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@15a306a. 2019-09-22 12:27:07.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:07.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:07.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:07.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:07.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:07.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:07.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:07.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:07.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:07.348 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:07.349 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack. 2019-09-22 12:27:07.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 460: Advanced to WAIT_REQUEST 2019-09-22 12:27:07.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction not completed 2019-09-22 12:27:07.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:07.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:12.353 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 460: Timeout at state WAIT_REQUEST. 3 retries remaining. 2019-09-22 12:27:12.357 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2019-09-22 12:27:12.360 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction ABORTED 2019-09-22 12:27:12.363 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2019-09-22 12:27:12.366 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2019-09-22 12:27:12.370 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:12.371 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:12.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:12.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:12.378 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:12.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:12.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:12.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:12.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:14.919 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6B 01 02 FA 79 2019-09-22 12:27:14.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=107, payload=6B 01 02 FA 2019-09-22 12:27:14.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=107, payload=6B 01 02 FA 2019-09-22 12:27:14.930 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:14.932 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:14.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 107 2019-09-22 12:27:14.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 460: (Callback 107) 2019-09-22 12:27:14.941 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2019-09-22 12:27:14.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 460: callback 107 2019-09-22 12:27:14.947 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=107, payload=6B 01 02 FA 2019-09-22 12:27:14.950 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 107, Status = Transmission complete, no ACK received(1) 2019-09-22 12:27:14.953 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction CANCELLED 2019-09-22 12:27:14.955 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2019-09-22 12:27:14.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: CANCEL while sending message. Requeueing - 2 attempts left! 2019-09-22 12:27:14.961 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction RESET with 2 retries remaining. 2019-09-22 12:27:14.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:27:14.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 460 to queue - size 18 2019-09-22 12:27:14.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:27:14.973 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6C 3D 2019-09-22 12:27:14.976 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6C 3D 2019-09-22 12:27:14.979 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:14.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:14.982 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:14.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:14.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction not completed 2019-09-22 12:27:14.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:14.991 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2019-09-22 12:27:14.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:14.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:14.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:14.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:14.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:15.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:15.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:15.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:15.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:15.007 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:15.009 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack. 2019-09-22 12:27:15.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 460: Advanced to WAIT_REQUEST 2019-09-22 12:27:15.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction not completed 2019-09-22 12:27:15.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:15.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:20.013 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 460: Timeout at state WAIT_REQUEST. 2 retries remaining. 2019-09-22 12:27:20.015 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2019-09-22 12:27:20.017 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction ABORTED 2019-09-22 12:27:20.021 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2019-09-22 12:27:20.025 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2019-09-22 12:27:20.028 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:20.030 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:20.031 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:20.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:20.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:20.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:20.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:20.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:20.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:22.645 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6C 01 02 FE 7A 2019-09-22 12:27:22.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=108, payload=6C 01 02 FE 2019-09-22 12:27:22.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=108, payload=6C 01 02 FE 2019-09-22 12:27:22.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:22.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:22.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 108 2019-09-22 12:27:22.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 460: (Callback 108) 2019-09-22 12:27:22.662 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2019-09-22 12:27:22.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 460: callback 108 2019-09-22 12:27:22.666 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=108, payload=6C 01 02 FE 2019-09-22 12:27:22.667 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 108, Status = Transmission complete, no ACK received(1) 2019-09-22 12:27:22.669 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction CANCELLED 2019-09-22 12:27:22.671 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2019-09-22 12:27:22.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: CANCEL while sending message. Requeueing - 1 attempts left! 2019-09-22 12:27:22.674 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction RESET with 1 retries remaining. 2019-09-22 12:27:22.676 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue 2019-09-22 12:27:22.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 460 to queue - size 18 2019-09-22 12:27:22.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:27:22.682 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6D 3C 2019-09-22 12:27:22.684 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0D 00 13 0C 06 84 04 00 0E 10 01 25 6D 3C 2019-09-22 12:27:22.686 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:22.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:22.689 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:22.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction not completed 2019-09-22 12:27:22.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:22.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:22.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:22.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:22.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:22.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:22.700 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2019-09-22 12:27:22.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:22.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:22.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:22.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:22.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:22.714 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:22.716 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack. 2019-09-22 12:27:22.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 460: Advanced to WAIT_REQUEST 2019-09-22 12:27:22.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction not completed 2019-09-22 12:27:22.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:22.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:24.659 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 05 07 60 0D 01 01 26 03 00 BC 2019-09-22 12:27:24.662 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 07 60 0D 01 01 26 03 00 2019-09-22 12:27:24.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 07 60 0D 01 01 26 03 00 2019-09-22 12:27:24.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:24.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:24.670 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:24.672 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:27:24.674 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1 2019-09-22 12:27:24.676 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL 2019-09-22 12:27:24.677 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT 2019-09-22 12:27:24.679 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Switch Multi Level report, value = 0 2019-09-22 12:27:24.681 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent 2019-09-22 12:27:24.683 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0 2019-09-22 12:27:24.686 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:switch_dimmer1 to 0 [PercentType] 2019-09-22 12:27:24.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:27:24.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@10696bc. 2019-09-22 12:27:24.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:24.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:24.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:24.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. ==> /var/log/openhab2/events.log <== 2019-09-22 12:27:24.707 [vent.ItemStateChangedEvent] - HallDimmer changed from 100 to 0 ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:27:25.640 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 05 0A 60 0D 01 01 31 05 04 22 01 58 C2 2019-09-22 12:27:25.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 01 58 2019-09-22 12:27:26.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 01 58 2019-09-22 12:27:26.201 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 05 0A 60 0D 01 01 31 05 04 22 01 58 C2 2019-09-22 12:27:26.203 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:26.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:26.206 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:26.206 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 01 58 2019-09-22 12:27:26.209 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:27:26.210 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1 2019-09-22 12:27:26.212 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL 2019-09-22 12:27:26.214 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 2019-09-22 12:27:26.216 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Type = Power(4), Scale = 0 2019-09-22 12:27:26.218 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Value = 34.4 2019-09-22 12:27:26.220 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2019-09-22 12:27:26.222 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=34.4 2019-09-22 12:27:26.226 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 5: Sensor conversion not performed for POWER. 2019-09-22 12:27:26.228 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:sensor_power1 to 34.4 [DecimalType] 2019-09-22 12:27:26.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:27:26.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a72e9d. 2019-09-22 12:27:26.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:26.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:26.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 0A 60 0D 01 01 31 05 04 22 01 58 2019-09-22 12:27:26.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:26.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE) 2019-09-22 12:27:26.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false 2019-09-22 12:27:26.246 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Decapsulating COMMAND_CLASS_MULTI_CHANNEL 2019-09-22 12:27:26.247 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1 2019-09-22 12:27:26.254 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL 2019-09-22 12:27:26.256 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 2019-09-22 12:27:26.258 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Type = Power(4), Scale = 0 2019-09-22 12:27:26.263 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 5: Sensor Value = 34.4 2019-09-22 12:27:26.265 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent 2019-09-22 12:27:26.267 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=34.4 2019-09-22 12:27:26.270 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 5: Sensor conversion not performed for POWER. 2019-09-22 12:27:26.272 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:f5074b06:node5:sensor_power1 to 34.4 [DecimalType] 2019-09-22 12:27:26.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1. 2019-09-22 12:27:26.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a56348. 2019-09-22 12:27:26.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:26.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1 2019-09-22 12:27:26.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:26.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:27.721 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 460: Timeout at state WAIT_REQUEST. 1 retries remaining. 2019-09-22 12:27:27.723 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2019-09-22 12:27:27.725 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction ABORTED 2019-09-22 12:27:27.727 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 2019-09-22 12:27:27.729 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 2019-09-22 12:27:27.731 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:27.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:27.734 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:27.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:27.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:27.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:27.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:27.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:27.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:29.724 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 6D 01 02 BF 3A 2019-09-22 12:27:29.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=109, payload=6D 01 02 BF 2019-09-22 12:27:29.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=109, payload=6D 01 02 BF 2019-09-22 12:27:29.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:29.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:29.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 460: [ABORTED] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:29.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 460: (Callback 109) 2019-09-22 12:27:29.744 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match! 2019-09-22 12:27:29.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 460: callback 109 2019-09-22 12:27:29.748 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=109, payload=6D 01 02 BF 2019-09-22 12:27:29.750 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 109, Status = Transmission complete, no ACK received(1) 2019-09-22 12:27:29.752 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 460: Transaction CANCELLED 2019-09-22 12:27:29.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2019-09-22 12:27:29.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Retry count exceeded. Discarding message: TID 460: [CANCELLED] priority=Immediate, requiresResponse=true, callback: 109 2019-09-22 12:27:29.757 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent 2019-09-22 12:27:29.760 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Setting OFFLINE ==> /var/log/openhab2/events.log <== 2019-09-22 12:27:29.766 [hingStatusInfoChangedEvent] - 'zwave:device:f5074b06:node12' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller ==> /var/log/openhab2/openhab.log <== 2019-09-22 12:27:29.764 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is DEAD 2019-09-22 12:27:29.770 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Node is DEAD. 2019-09-22 12:27:29.773 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveNodeStatusEvent 2019-09-22 12:27:29.776 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Setting OFFLINE 2019-09-22 12:27:29.781 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 12: Node Status event - Node is DEAD 2019-09-22 12:27:29.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 460: Transaction completed 2019-09-22 12:27:29.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:460 CANCELLED 2019-09-22 12:27:29.789 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2019-09-22 12:27:29.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:29.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false. 2019-09-22 12:27:29.802 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0C 02 84 05 25 6E 21 2019-09-22 12:27:29.805 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 09 00 13 0C 02 84 05 25 6E 21 2019-09-22 12:27:29.808 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT 2019-09-22 12:27:29.811 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06 2019-09-22 12:27:29.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 461: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 110 2019-09-22 12:27:29.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:29.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload= 2019-09-22 12:27:29.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 461: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 110 2019-09-22 12:27:29.820 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2019-09-22 12:27:29.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK 2019-09-22 12:27:29.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:29.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:29.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:29.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:29.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 461: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 110 2019-09-22 12:27:29.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1 2019-09-22 12:27:29.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 461: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 110 2019-09-22 12:27:29.839 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 2019-09-22 12:27:29.841 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack. 2019-09-22 12:27:29.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 461: Advanced to WAIT_REQUEST 2019-09-22 12:27:29.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 461: Transaction not completed 2019-09-22 12:27:29.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty 2019-09-22 12:27:29.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 2019-09-22 12:27:34.844 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 12: TID 461: Timeout at state WAIT_REQUEST. 3 retries remaining. 2019-09-22 12:27:34.846 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction! 2019-09-22 12:27:34.859 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 461: Transaction ABORTED