DSB05 Aeon Sensor - only battery level updated - all other channels remain NaN

peter_h · February 25, 2018, 1:24pm

Hello,
I am running the latest openHABian on a Raspberry pi 3 with Razberry2, openhab v 2.2.0-1 and zwave binding v2.2. Included items are 2 DSB05 Aeon mutli sensors (one battery powered, one permamently powered via usb) and one FGMS001 Fibaro multi sensor.

Whereas the Fibaro sensor works perfectly fine, both DSB05 sensors show the same odd behaivior (eg after restarting the raspi):
the binary-sensor switch goes to on, all other channels (temp, hum, lum, battery) remain uninitialized. After a while the battery channel will be updated (100% for usb powered, 72% to the battery powered one). The motion switch / binary-sensor toggles every 30min or so without an obvious reason, the other relevant channels temperature, humidity and lumen remain in a frozen state forever (shown as NaN in PaperUI).

The problem seems to be similar to the thread: https://community.openhab.org/t/zwave-dsb05-4-in-one-multisensor-nan/16949 . However, simply removing / adding batteries or un/re-powering the sensors does not solve the problem…

The only immediate reaction to a movement in front of the sensor that is shown in the zwave.log file is the following one line:

25-Feb-2018 14:16:02.967 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255

Snapshot of the zwave.log file with NODE-4 relevance:

25-Feb-2018 14:06:50.978 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:06:52.309 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:06:56.577 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:07:30.545 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 14:07:30.548 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 14:07:30.553 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BASIC
25-Feb-2018 14:07:30.556 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class BASIC, passing to handleApplicationCommandRequest
25-Feb-2018 14:07:30.558 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Received Basic Request
25-Feb-2018 14:07:30.561 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic Set sent to the controller will be processed as Basic Report
25-Feb-2018 14:07:30.565 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic report, value = 0x00
25-Feb-2018 14:07:30.571 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
25-Feb-2018 14:07:30.574 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 0
25-Feb-2018 14:07:30.577 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 14:10:08.834 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 14:10:08.835 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 14:10:08.841 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BASIC
25-Feb-2018 14:10:08.843 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class BASIC, passing to handleApplicationCommandRequest
25-Feb-2018 14:10:08.846 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Received Basic Request
25-Feb-2018 14:10:08.848 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic Set sent to the controller will be processed as Basic Report
25-Feb-2018 14:10:08.851 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic report, value = 0xFF
25-Feb-2018 14:10:08.856 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
25-Feb-2018 14:10:08.859 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
25-Feb-2018 14:10:08.862 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 14:10:34.828 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:10:38.535 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 14:10:38.536 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 14:10:38.539 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class WAKE_UP
25-Feb-2018 14:10:38.541 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class WAKE_UP, passing to handleApplicationCommandRequest
25-Feb-2018 14:10:38.542 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request
25-Feb-2018 14:10:38.543 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received WAKE_UP_NOTIFICATION
25-Feb-2018 14:10:38.545 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 0 messages in the wake-up queue.
25-Feb-2018 14:10:38.549 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveWakeUpEvent
25-Feb-2018 14:10:39.574 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: No more messages, go back to sleep
25-Feb-2018 14:10:39.575 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
25-Feb-2018 14:10:39.577 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 4: Creating empty message of class = SendData (0x13), type = Request (0x00)
25-Feb-2018 14:10:39.589 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 84 08 25 A3 E9
25-Feb-2018 14:10:39.663 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
25-Feb-2018 14:10:40.395 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 163, Status = Transmission complete, no ACK received(1)
25-Feb-2018 14:10:40.405 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
25-Feb-2018 14:10:40.408 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Went to sleep
25-Feb-2018 14:10:40.409 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is sleeping
25-Feb-2018 14:10:40.411 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
25-Feb-2018 14:10:40.412 [DEBUG] [.internal.protocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 794ms/2229ms.
25-Feb-2018 14:10:52.190 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:13:30.902 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:14:39.544 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 14:14:39.546 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 14:14:39.586 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class WAKE_UP
25-Feb-2018 14:14:39.588 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class WAKE_UP, passing to handleApplicationCommandRequest
25-Feb-2018 14:14:39.589 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request
25-Feb-2018 14:14:39.590 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received WAKE_UP_NOTIFICATION
25-Feb-2018 14:14:39.592 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 0 messages in the wake-up queue.
25-Feb-2018 14:14:39.595 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveWakeUpEvent
25-Feb-2018 14:14:40.615 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: No more messages, go back to sleep
25-Feb-2018 14:14:40.617 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
25-Feb-2018 14:14:40.620 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 4: Creating empty message of class = SendData (0x13), type = Request (0x00)
25-Feb-2018 14:14:40.636 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 84 08 25 A4 EE
25-Feb-2018 14:14:40.714 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
25-Feb-2018 14:14:41.448 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 164, Status = Transmission complete, no ACK received(1)
25-Feb-2018 14:14:41.459 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
25-Feb-2018 14:14:41.461 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Went to sleep
25-Feb-2018 14:14:41.463 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is sleeping
25-Feb-2018 14:14:41.464 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
25-Feb-2018 14:14:41.466 [DEBUG] [.internal.protocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 797ms/2229ms.
25-Feb-2018 14:15:39.907 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:16:02.967 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 14:17:09.568 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255

One last remark: DSB05 sensors worked fine with openhab1 and still work fine on a different raspi with z-way…

chris · February 25, 2018, 1:55pm

There must be more in the log than this line. Please provide the unfiltered log so I can see what is happening.

peter_h · February 25, 2018, 3:51pm

zwave.log:

25-Feb-2018 13:31:55.341 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:5a0ca91c:node3:sensor_luminance to 1368 [DecimalType]
25-Feb-2018 13:31:55.363 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 13:33:25.278 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:33:25.282 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 04 4D 52 3C AF 
25-Feb-2018 13:33:25.285 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 04 4D 52 3C AF 
25-Feb-2018 13:33:25.286 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xAF
25-Feb-2018 13:33:25.287 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:33:25.290 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 03 0A 56 01 31 05 03 0A 04 4D 52 3C 
25-Feb-2018 13:33:25.291 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:33:25.316 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:33:25.318 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:33:25.319 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xAF
25-Feb-2018 13:33:25.322 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 04 4D 52 3C AF 
25-Feb-2018 13:33:25.324 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 04 4D 52 3C AF 
25-Feb-2018 13:33:25.333 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 0A 56 01 31 05 03 0A 04 4D 52 3C 
25-Feb-2018 13:33:25.335 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:33:25.336 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - Handle Message Application Command Request
25-Feb-2018 13:33:25.337 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DETAILS)
25-Feb-2018 13:33:25.338 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Incoming command class CRC_16_ENCAP
25-Feb-2018 13:33:25.339 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Found Command Class CRC_16_ENCAP, passing to handleApplicationCommandRequest
25-Feb-2018 13:33:25.340 [DEBUG] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - NODE 3: Received CRC 16 Encapsulation Request
25-Feb-2018 13:33:25.340 [TRACE] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - Process CRC16 Encapsulation
25-Feb-2018 13:33:25.341 [DEBUG] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - NODE 3: Calling handleApplicationCommandRequest.
25-Feb-2018 13:33:25.342 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V8
25-Feb-2018 13:33:25.343 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Multi Level REPORT received
25-Feb-2018 13:33:25.344 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Type = Luminance(3), Scale = 1
25-Feb-2018 13:33:25.345 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Value = 1101
25-Feb-2018 13:33:25.347 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
25-Feb-2018 13:33:25.348 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
25-Feb-2018 13:33:25.349 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 1101
25-Feb-2018 13:33:25.350 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:5a0ca91c:node3:sensor_luminance to 1101 [DecimalType]
25-Feb-2018 13:33:25.353 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 13:34:33.510 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:34:33.516 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 04 02 84 07 76 
25-Feb-2018 13:34:33.520 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 00 04 00 04 02 84 07 76 
25-Feb-2018 13:34:33.523 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x76
25-Feb-2018 13:34:33.525 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:34:33.528 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 04 02 84 07 
25-Feb-2018 13:34:33.531 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:34:33.556 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:34:33.559 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:34:33.561 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x76
25-Feb-2018 13:34:33.564 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 04 02 84 07 76 
25-Feb-2018 13:34:33.567 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 04 02 84 07 76 
25-Feb-2018 13:34:33.570 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 84 07 
25-Feb-2018 13:34:33.572 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:34:33.573 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - Handle Message Application Command Request
25-Feb-2018 13:34:33.575 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 13:34:33.576 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 13:34:33.578 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@a2a603 already registered
25-Feb-2018 13:34:33.579 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class WAKE_UP
25-Feb-2018 13:34:33.581 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class WAKE_UP, passing to handleApplicationCommandRequest
25-Feb-2018 13:34:33.582 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received Wake Up Request
25-Feb-2018 13:34:33.584 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Received WAKE_UP_NOTIFICATION
25-Feb-2018 13:34:33.585 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is awake with 0 messages in the wake-up queue.
25-Feb-2018 13:34:33.587 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
25-Feb-2018 13:34:33.590 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveWakeUpEvent
25-Feb-2018 13:34:33.622 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=147, payload=04 02 84 08 
25-Feb-2018 13:34:33.623 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 84 07 
25-Feb-2018 13:34:33.624 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=147, expected=SendData, cancelled=true      MISMATCH
25-Feb-2018 13:34:34.622 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: No more messages, go back to sleep
25-Feb-2018 13:34:34.623 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
25-Feb-2018 13:34:34.625 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 4: Creating empty message of class = SendData (0x13), type = Request (0x00)
25-Feb-2018 13:34:34.626 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Callback ID = 148
25-Feb-2018 13:34:34.628 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
25-Feb-2018 13:34:34.628 [DEBUG] [.internal.protocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
25-Feb-2018 13:34:34.629 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xDE
25-Feb-2018 13:34:34.632 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 04 02 84 08 25 94 DE 
25-Feb-2018 13:34:34.635 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 84 08 25 94 DE 
25-Feb-2018 13:34:34.640 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received ACK
25-Feb-2018 13:34:34.642 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:34:34.648 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
25-Feb-2018 13:34:34.663 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 
25-Feb-2018 13:34:34.666 [TRACE] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
25-Feb-2018 13:34:34.667 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
25-Feb-2018 13:34:34.668 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:34:34.670 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 
25-Feb-2018 13:34:34.672 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:34:34.696 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:34:34.698 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:34:34.698 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:34:34.700 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xE8
25-Feb-2018 13:34:34.703 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
25-Feb-2018 13:34:34.703 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 94 00 00 02 7D 
25-Feb-2018 13:34:34.705 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
25-Feb-2018 13:34:34.706 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 94 00 00 02 7D 
25-Feb-2018 13:34:34.707 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x7D
25-Feb-2018 13:34:34.708 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
25-Feb-2018 13:34:34.709 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
25-Feb-2018 13:34:34.709 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:34:34.711 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
25-Feb-2018 13:34:34.711 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 94 00 00 02 
25-Feb-2018 13:34:34.712 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
25-Feb-2018 13:34:34.713 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:34:34.714 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Ack Pending cleared
25-Feb-2018 13:34:34.736 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:34:34.740 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:34:34.742 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x73
25-Feb-2018 13:34:34.744 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 94 00 00 02 00 00 73 
25-Feb-2018 13:34:34.747 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 94 00 00 02 00 00 73 
25-Feb-2018 13:34:34.750 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=94 00 00 02 
25-Feb-2018 13:34:34.751 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:34:34.752 [TRACE] [ternal.protocol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
25-Feb-2018 13:34:34.754 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 148, Status = Transmission complete and ACK received(0)
25-Feb-2018 13:34:34.756 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 13:34:34.758 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@a2a603 already registered
25-Feb-2018 13:34:34.760 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=148, payload=04 02 84 08 
25-Feb-2018 13:34:34.763 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=94 00 00 02 
25-Feb-2018 13:34:34.764 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=148, expected=SendData, cancelled=false        transaction complete!
25-Feb-2018 13:34:34.766 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
25-Feb-2018 13:34:34.768 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Went to sleep
25-Feb-2018 13:34:34.769 [DEBUG] [rnal.protocol.commandclass.ZWaveWakeUpCommandClass] - NODE 4: Is sleeping
25-Feb-2018 13:34:34.770 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
25-Feb-2018 13:34:34.772 [DEBUG] [.internal.protocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 104ms/2229ms.
25-Feb-2018 13:34:34.773 [TRACE] [.internal.protocol.ZWaveController$ZWaveSendThread] - Acquired. Transaction completed permit count -> 0
25-Feb-2018 13:34:34.774 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Released. Transaction completed permit count -> 0
25-Feb-2018 13:35:01.658 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:35:01.666 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 18 
25-Feb-2018 13:35:01.673 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 18 
25-Feb-2018 13:35:01.676 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x18
25-Feb-2018 13:35:01.679 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:35:01.684 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 
25-Feb-2018 13:35:01.687 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:35:01.716 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:35:01.720 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:35:01.722 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x18
25-Feb-2018 13:35:01.727 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 18 
25-Feb-2018 13:35:01.732 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 18 
25-Feb-2018 13:35:01.738 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 03 0A 56 01 31 05 03 0A 02 F0 8E EC 
25-Feb-2018 13:35:01.740 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:35:01.742 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - Handle Message Application Command Request
25-Feb-2018 13:35:01.744 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Application Command Request (ALIVE:DETAILS)
25-Feb-2018 13:35:01.747 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Incoming command class CRC_16_ENCAP
25-Feb-2018 13:35:01.749 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 3: Found Command Class CRC_16_ENCAP, passing to handleApplicationCommandRequest
25-Feb-2018 13:35:01.751 [DEBUG] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - NODE 3: Received CRC 16 Encapsulation Request
25-Feb-2018 13:35:01.753 [TRACE] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - Process CRC16 Encapsulation
25-Feb-2018 13:35:01.755 [DEBUG] [l.commandclass.ZWaveCRC16EncapsulationCommandClass] - NODE 3: Calling handleApplicationCommandRequest.
25-Feb-2018 13:35:01.758 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V8
25-Feb-2018 13:35:01.760 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Multi Level REPORT received
25-Feb-2018 13:35:01.762 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Type = Luminance(3), Scale = 1
25-Feb-2018 13:35:01.765 [DEBUG] [col.commandclass.ZWaveMultiLevelSensorCommandClass] - NODE 3: Sensor Value = 752
25-Feb-2018 13:35:01.767 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
25-Feb-2018 13:35:01.769 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
25-Feb-2018 13:35:01.772 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 752
25-Feb-2018 13:35:01.775 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:5a0ca91c:node3:sensor_luminance to 752 [DecimalType]
25-Feb-2018 13:35:01.781 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
25-Feb-2018 13:35:16.509 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:35:16.516 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 04 03 20 01 00 D4 
25-Feb-2018 13:35:16.521 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 09 00 04 00 04 03 20 01 00 D4 
25-Feb-2018 13:35:16.523 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xD4
25-Feb-2018 13:35:16.538 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:35:16.541 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 04 03 20 01 00 
25-Feb-2018 13:35:16.543 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:35:16.566 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:35:16.569 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:35:16.571 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0xD4
25-Feb-2018 13:35:16.576 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 04 03 20 01 00 D4 
25-Feb-2018 13:35:16.582 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 04 03 20 01 00 D4 
25-Feb-2018 13:35:16.587 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 20 01 00 
25-Feb-2018 13:35:16.590 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:35:16.593 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - Handle Message Application Command Request
25-Feb-2018 13:35:16.595 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 13:35:16.598 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 13:35:16.600 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@a2a603 already registered
25-Feb-2018 13:35:16.602 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BASIC
25-Feb-2018 13:35:16.604 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class BASIC, passing to handleApplicationCommandRequest
25-Feb-2018 13:35:16.605 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Received Basic Request
25-Feb-2018 13:35:16.606 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic Set sent to the controller will be processed as Basic Report
25-Feb-2018 13:35:16.608 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic report, value = 0x00
25-Feb-2018 13:35:16.609 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
25-Feb-2018 13:35:16.611 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
25-Feb-2018 13:35:16.612 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 0
25-Feb-2018 13:35:16.614 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:35:16.619 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=148, payload=04 02 84 08 
25-Feb-2018 13:35:16.622 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 20 01 00 
25-Feb-2018 13:35:16.624 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=148, expected=SendData, cancelled=false      MISMATCH
25-Feb-2018 13:35:56.698 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
25-Feb-2018 13:35:56.704 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 04 03 20 01 FF 2B 
25-Feb-2018 13:35:56.708 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 09 00 04 00 04 03 20 01 FF 2B 
25-Feb-2018 13:35:56.711 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x2B
25-Feb-2018 13:35:56.712 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
25-Feb-2018 13:35:56.715 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 04 03 20 01 FF 
25-Feb-2018 13:35:56.717 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
25-Feb-2018 13:35:56.746 [TRACE] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT
25-Feb-2018 13:35:56.749 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
25-Feb-2018 13:35:56.751 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - Calculated checksum = 0x2B
25-Feb-2018 13:35:56.756 [DEBUG] [nhab.binding.zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 04 03 20 01 FF 2B 
25-Feb-2018 13:35:56.760 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 04 03 20 01 FF 2B 
25-Feb-2018 13:35:56.764 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 20 01 FF 
25-Feb-2018 13:35:56.765 [TRACE] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
25-Feb-2018 13:35:56.767 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - Handle Message Application Command Request
25-Feb-2018 13:35:56.769 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Application Command Request (ALIVE:DONE)
25-Feb-2018 13:35:56.770 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 4: Starting initialisation from DONE
25-Feb-2018 13:35:56.772 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@a2a603 already registered
25-Feb-2018 13:35:56.774 [DEBUG] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Incoming command class BASIC
25-Feb-2018 13:35:56.776 [TRACE] [tocol.serialmessage.ApplicationCommandMessageClass] - NODE 4: Found Command Class BASIC, passing to handleApplicationCommandRequest
25-Feb-2018 13:35:56.777 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Received Basic Request
25-Feb-2018 13:35:56.779 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic Set sent to the controller will be processed as Basic Report
25-Feb-2018 13:35:56.780 [DEBUG] [ernal.protocol.commandclass.ZWaveBasicCommandClass] - NODE 4: Basic report, value = 0xFF
25-Feb-2018 13:35:56.782 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
25-Feb-2018 13:35:56.783 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
25-Feb-2018 13:35:56.785 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
25-Feb-2018 13:35:56.788 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:35:56.794 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=4, callback=148, payload=04 02 84 08 
25-Feb-2018 13:35:56.803 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 03 20 01 FF 
25-Feb-2018 13:35:56.805 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=148, expected=SendData, cancelled=false      MISMATCH

chris · February 25, 2018, 4:13pm

From the log it looks like it’s updating the binary sensor channel just fine -:

peter_h · February 25, 2018, 5:01pm

hmmm - any clue why
a) the other channels are not update (temperature, …)?
b) with respect to the update of the motion-switch, this happens from time but seems to be not connected to any movement triggered in front of the sensor. see also log below (filtered to only “update channel” of that particular node 4). Even when ON event is triggered, the next OFF event is not within seconds (as supposed to be) but many minutes later…

25-Feb-2018 11:30:12.854 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 11:30:13.056 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 11:30:13.099 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 11:51:14.697 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 11:52:41.919 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:02:20.831 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:02:20.929 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:03:55.659 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 12:09:30.634 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:13:29.675 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 12:13:37.765 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:18:09.668 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 12:30:21.781 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 12:30:21.899 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 12:43:54.152 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 12:47:53.615 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:01:44.447 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:02:23.758 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:02:23.859 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:02:23.901 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:07:43.614 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:08:12.509 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:12:11.615 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:16:22.243 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:24:53.605 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:26:14.382 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:30:31.821 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:35:16.614 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]
25-Feb-2018 13:35:56.788 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to ON [OnOffType]
25-Feb-2018 13:52:09.602 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:5a0ca91c:node4:sensor_binary to OFF [OnOffType]