Z-Wave not polling after restart

schalli · March 17, 2021, 9:29pm

I recently added a couple of Leviton DZ6HD dimmers to my Z-Wave network, and they seemed to work fine. I was able to send commands from Openhab to the dimmers, and they reported changes back to OH3.

After a while, however, they stop reporting changes, but still accept commands.
While investigating, I discovered Z-Wave is reporting this in the log:

[ZWaveVersionCommandClass] - NODE 2: Command Class COMMAND_CLASS_HAIL has version 0!

I modified the code to not discard command class 0, and started seeing this in the log, when I toggle the dimmer on the switch:

2021-03-17 14:08:05.357 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 14:08:05.359 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 02 82 01 D0 00 A2
2021-03-17 14:08:05.362 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 14:08:05.363 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 14:08:05.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D0 00
2021-03-17 14:08:05.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D0 00
2021-03-17 14:08:05.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 14:08:05.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 14:08:05.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 14:08:05.367 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2021-03-17 14:08:05.368 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 14:08:05.368 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_HAIL V0 HAIL
2021-03-17 14:08:05.369 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2021-03-17 14:08:05.370 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2021-03-17 14:08:05.370 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 86400 seconds - start in 75 milliseconds.
2021-03-17 14:08:05.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 14:08:05.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3b048b77.
2021-03-17 14:08:05.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 14:08:05.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 14:08:05.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 14:08:05.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 14:08:05.374 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 14:08:05.682 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 14:08:05.683 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 02 82 01 D0 00 A2
2021-03-17 14:08:05.684 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 14:08:05.685 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 14:08:05.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D0 00
2021-03-17 14:08:05.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D0 00
2021-03-17 14:08:05.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 14:08:05.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 14:08:05.686 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 14:08:05.687 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2021-03-17 14:08:05.687 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 14:08:05.687 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_HAIL V0 HAIL
2021-03-17 14:08:05.688 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2021-03-17 14:08:05.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2021-03-17 14:08:05.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 86400 seconds - start in 75 milliseconds.
2021-03-17 14:08:05.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 14:08:05.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@75e743a3.
2021-03-17 14:08:05.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 14:08:05.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 14:08:05.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 14:08:05.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 14:08:05.690 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

Can someone (@chris , maybe? :> ) help me understand this?
Is Leviton violating the protocol by reporting command version 0?
Can we fix this on OH3 side?

Thanks,
Daniel

schalli · March 17, 2021, 10:48pm

Interestingly, after changing the channel’s profile from Default to (No Profile) (effectively a noop), the status is correctly polled when the device hails:

2021-03-17 15:43:23.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2021-03-17 15:45:08.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:949245ad36:node2:switch_dimmer unlinked - polling stopped.
2021-03-17 15:45:08.270 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:949245ad36:node2:switch_dimmer linked - polling started.
2021-03-17 15:45:47.719 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:47.720 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 02 82 01 D5 00 A7
2021-03-17 15:45:47.721 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 0A 00 04 00 02 02 82 01 D5 00 A7
2021-03-17 15:45:47.721 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -89
2021-03-17 15:45:47.721 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:47.722 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Message payload = 00 02 02 82 01 D5 00
2021-03-17 15:45:47.722 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:47.722 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:47.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D5 00
2021-03-17 15:45:47.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D5 00
2021-03-17 15:45:47.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 15:45:47.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 15:45:47.724 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:47.724 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2021-03-17 15:45:47.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:47.725 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_HAIL V0 HAIL
2021-03-17 15:45:47.725 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2021-03-17 15:45:47.725 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2021-03-17 15:45:47.726 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 1800 seconds - start in 75 milliseconds.
2021-03-17 15:45:47.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 15:45:47.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7df26f55.
2021-03-17 15:45:47.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:47.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:47.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:47.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:47.727 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 15:45:47.801 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2021-03-17 15:45:47.801 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:949245ad36:node2:switch_dimmer
2021-03-17 15:45:47.802 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2021-03-17 15:45:47.802 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2021-03-17 15:45:47.803 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 0
2021-03-17 15:45:47.803 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:47.803 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2021-03-17 15:45:47.804 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:949245ad36:node2:switch_dimmer on COMMAND_CLASS_BASIC
2021-03-17 15:45:47.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2021-03-17 15:45:47.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 120 to queue - size 1
2021-03-17 15:45:47.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:47.805 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == true, frequentlyListening == false, awake == false
2021-03-17 15:45:47.806 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2021-03-17 15:45:47.806 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2021-03-17 15:45:47.807 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Creating empty message of class = SendData (0x13), type = Request
2021-03-17 15:45:47.807 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -88
2021-03-17 15:45:47.807 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 4C A8
2021-03-17 15:45:47.808 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 4C A8
2021-03-17 15:45:47.808 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-03-17 15:45:47.810 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-03-17 15:45:47.810 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
2021-03-17 15:45:47.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-17 15:45:47.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-17 15:45:47.812 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: Transaction Start type SendData
2021-03-17 15:45:47.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 15:45:47.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 120: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-03-17 15:45:47.813 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SWITCH_MULTILEVEL
2021-03-17 15:45:47.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:47.813 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
2021-03-17 15:45:47.814 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2021-03-17 15:45:47.815 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:47.816 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:49 PDT 2021 - 1999ms
2021-03-17 15:45:47.817 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 120: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.817 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2021-03-17 15:45:47.817 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:47.818 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
2021-03-17 15:45:47.818 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:49 PDT 2021 - 1996ms
2021-03-17 15:45:47.819 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24
2021-03-17 15:45:47.820 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:47.820 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
2021-03-17 15:45:47.821 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:47.822 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:47.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:47.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-17 15:45:47.826 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2021-03-17 15:45:47.827 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:47.827 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:49 PDT 2021 - 1987ms
2021-03-17 15:45:47.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:47.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 120: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-17 15:45:47.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 120: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.830 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:47.830 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2021-03-17 15:45:47.831 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
2021-03-17 15:45:47.831 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2021-03-17 15:45:47.831 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance ST: WAIT_RESPONSE
2021-03-17 15:45:47.832 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:47.832 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:47.833 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance TO: WAIT_REQUEST
2021-03-17 15:45:47.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 120: Advanced to WAIT_REQUEST
2021-03-17 15:45:47.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 120: Transaction not completed
2021-03-17 15:45:47.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:47.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-17 15:45:47.834 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2021-03-17 15:45:47.834 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:47.835 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:47.835 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:52 PDT 2021 - 4998ms
2021-03-17 15:45:47.836 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 6F
2021-03-17 15:45:47.837 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 18 00 13 4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 6F
2021-03-17 15:45:47.837 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 111
2021-03-17 15:45:47.837 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:47.837 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:47.838 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:47.838 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:47.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=76, payload=4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:47.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=76, payload=4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:47.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 120: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-17 15:45:47.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 120: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 76
2021-03-17 15:45:47.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 120: (Callback 76)
2021-03-17 15:45:47.840 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-03-17 15:45:47.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 120: callback 76
2021-03-17 15:45:47.841 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=76, payload=4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:47.841 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2021-03-17 15:45:47.842 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
2021-03-17 15:45:47.842 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 76, Status = Transmission complete and ACK received(0)
2021-03-17 15:45:47.842 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:47.843 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance ST: WAIT_REQUEST
2021-03-17 15:45:47.843 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:47.843 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=76, payload=4C 00 00 02 00 D4 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:47.844 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
2021-03-17 15:45:47.844 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance TO: WAIT_DATA
2021-03-17 15:45:47.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 120: Advanced to WAIT_DATA
2021-03-17 15:45:47.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 120: Transaction not completed
2021-03-17 15:45:47.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:47.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-17 15:45:47.845 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 15:45:47.845 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:47.846 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:52 PDT 2021 - 4998ms
2021-03-17 15:45:47.849 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:47.850 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 05 26 03 56 56 00 D4 00 00
2021-03-17 15:45:47.850 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 0D 00 04 00 02 05 26 03 56 56 00 D4 00 00
2021-03-17 15:45:47.850 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0
2021-03-17 15:45:47.851 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:47.851 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Message payload = 00 02 05 26 03 56 56 00 D4 00
2021-03-17 15:45:47.851 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:47.852 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:47.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 56 56 00 D4 00
2021-03-17 15:45:47.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 56 56 00 D4 00
2021-03-17 15:45:47.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 15:45:47.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 15:45:47.853 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:47.854 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2021-03-17 15:45:47.854 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:47.854 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2021-03-17 15:45:47.854 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 86
2021-03-17 15:45:47.855 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2021-03-17 15:45:47.855 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2021-03-17 15:45:47.855 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=86
2021-03-17 15:45:47.856 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:switch_dimmer, cmdClass=COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint=0
2021-03-17 15:45:47.856 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:949245ad36:node2:switch_dimmer to 86 [PercentType]
2021-03-17 15:45:47.857 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:switch_dimmer, cmdClass=COMMAND_CLASS_BASIC, endpoint=0
2021-03-17 15:45:47.857 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:scene_number, cmdClass=COMMAND_CLASS_SCENE_ACTIVATION, endpoint=0
2021-03-17 15:45:47.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 15:45:47.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6c5cd871.
2021-03-17 15:45:47.858 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction 120  ApplicationCommandHandler.
2021-03-17 15:45:47.859 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : state >> WAIT_DATA
2021-03-17 15:45:47.859 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : node  >> 2
2021-03-17 15:45:47.859 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : class >> 38 == 38.
2021-03-17 15:45:47.860 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : commd >> 3 == 3.
2021-03-17 15:45:47.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6c5cd871.
2021-03-17 15:45:47.860 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance ST: WAIT_DATA
2021-03-17 15:45:47.861 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:47.862 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance RX: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 56 56 00 D4 00
2021-03-17 15:45:47.862 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 120: TransactionAdvance TO: DONE
2021-03-17 15:45:47.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:120 DONE
2021-03-17 15:45:47.863 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2021-03-17 15:45:47.864 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-03-17 15:45:47.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2021-03-17 15:45:47.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:47.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:47.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:47.865 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 15:45:47.865 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:49.635 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:49.637 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 02 02 82 01 D2 00 A0
2021-03-17 15:45:49.638 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 0A 00 04 00 02 02 82 01 D2 00 A0
2021-03-17 15:45:49.639 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -96
2021-03-17 15:45:49.639 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:49.639 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Message payload = 00 02 02 82 01 D2 00
2021-03-17 15:45:49.640 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:49.640 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:49.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D2 00
2021-03-17 15:45:49.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 02 82 01 D2 00
2021-03-17 15:45:49.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 15:45:49.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 15:45:49.643 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:49.644 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2021-03-17 15:45:49.644 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:49.645 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_HAIL V0 HAIL
2021-03-17 15:45:49.646 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveDelayedPollEvent
2021-03-17 15:45:49.649 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2021-03-17 15:45:49.650 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling initialised at 1800 seconds - start in 75 milliseconds.
2021-03-17 15:45:49.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 15:45:49.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7ae05a45.
2021-03-17 15:45:49.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:49.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:49.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:49.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:49.654 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 15:45:49.725 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling...
2021-03-17 15:45:49.726 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling zwave:device:949245ad36:node2:switch_dimmer
2021-03-17 15:45:49.726 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 2: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2021-03-17 15:45:49.727 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2021-03-17 15:45:49.727 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Encapsulating message, endpoint 0
2021-03-17 15:45:49.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:49.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2021-03-17 15:45:49.729 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling skipped for zwave:device:949245ad36:node2:switch_dimmer on COMMAND_CLASS_BASIC
2021-03-17 15:45:49.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Adding to device queue
2021-03-17 15:45:49.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added 121 to queue - size 1
2021-03-17 15:45:49.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:49.731 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == true, frequentlyListening == false, awake == false
2021-03-17 15:45:49.731 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2021-03-17 15:45:49.731 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2021-03-17 15:45:49.732 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Creating empty message of class = SendData (0x13), type = Request
2021-03-17 15:45:49.732 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -87
2021-03-17 15:45:49.733 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 26 02 25 4D A9
2021-03-17 15:45:49.734 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 4D A9
2021-03-17 15:45:49.734 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-03-17 15:45:49.735 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: Transaction Start type SendData
2021-03-17 15:45:49.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 121: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.736 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SWITCH_MULTILEVEL
2021-03-17 15:45:49.737 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
2021-03-17 15:45:49.738 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2021-03-17 15:45:49.738 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:51 PDT 2021 - 2000ms
2021-03-17 15:45:49.739 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 121: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.739 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:49.740 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:51 PDT 2021 - 1998ms
2021-03-17 15:45:49.741 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-03-17 15:45:49.742 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
2021-03-17 15:45:49.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-17 15:45:49.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-17 15:45:49.743 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:49.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-03-17 15:45:49.744 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2021-03-17 15:45:49.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:49.745 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
2021-03-17 15:45:49.745 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -24
2021-03-17 15:45:49.746 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:49.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-17 15:45:49.747 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
2021-03-17 15:45:49.747 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:49.747 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2021-03-17 15:45:49.748 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:49.748 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:51 PDT 2021 - 1990ms
2021-03-17 15:45:49.748 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:49.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:49.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:49.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-17 15:45:49.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.754 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:49.755 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2021-03-17 15:45:49.756 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
2021-03-17 15:45:49.757 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: sentData successfully placed on stack.
2021-03-17 15:45:49.758 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance ST: WAIT_RESPONSE
2021-03-17 15:45:49.759 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:49.760 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2021-03-17 15:45:49.761 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:49.761 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance TO: WAIT_REQUEST
2021-03-17 15:45:49.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 121: Advanced to WAIT_REQUEST
2021-03-17 15:45:49.764 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 68
2021-03-17 15:45:49.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 121: Transaction not completed
2021-03-17 15:45:49.765 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 18 00 13 4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 68
2021-03-17 15:45:49.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:49.765 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 104
2021-03-17 15:45:49.766 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:49.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-17 15:45:49.766 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 0: Message payload = 4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:49.767 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:49.767 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2021-03-17 15:45:49.767 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:49.767 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2021-03-17 15:45:49.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=77, payload=4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:49.768 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Mar 17 15:45:54 PDT 2021 - 4996ms
2021-03-17 15:45:49.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=77, payload=4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:49.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-17 15:45:49.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 77
2021-03-17 15:45:49.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 121: (Callback 77)
2021-03-17 15:45:49.774 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-03-17 15:45:49.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 121: callback 77
2021-03-17 15:45:49.775 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2021-03-17 15:45:49.776 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=77, payload=4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:49.776 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 02 05 26 03 63 63 00 D2 00 06
2021-03-17 15:45:49.777 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 0D 00 04 00 02 05 26 03 63 63 00 D2 00 06
2021-03-17 15:45:49.777 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2021-03-17 15:45:49.777 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 6
2021-03-17 15:45:49.778 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2021-03-17 15:45:49.779 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Message payload = 00 02 05 26 03 63 63 00 D2 00
2021-03-17 15:45:49.779 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
2021-03-17 15:45:49.779 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2021-03-17 15:45:49.780 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2021-03-17 15:45:49.780 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 77, Status = Transmission complete and ACK received(0)
2021-03-17 15:45:49.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 63 63 00 D2 00
2021-03-17 15:45:49.781 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:49.782 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance ST: WAIT_REQUEST
2021-03-17 15:45:49.783 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:49.784 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=77, payload=4D 00 00 02 00 D2 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00
2021-03-17 15:45:49.785 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
2021-03-17 15:45:49.786 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance TO: WAIT_DATA
2021-03-17 15:45:49.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 121: Advanced to WAIT_DATA
2021-03-17 15:45:49.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 121: Transaction not completed
2021-03-17 15:45:49.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 63 63 00 D2 00
2021-03-17 15:45:49.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2021-03-17 15:45:49.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2021-03-17 15:45:49.791 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2021-03-17 15:45:49.792 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2021-03-17 15:45:49.793 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY not supported
2021-03-17 15:45:49.793 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2021-03-17 15:45:49.796 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 2: Switch Multi Level report, value = 99
2021-03-17 15:45:49.796 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2021-03-17 15:45:49.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2021-03-17 15:45:49.798 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=99
2021-03-17 15:45:49.798 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:switch_dimmer, cmdClass=COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint=0
2021-03-17 15:45:49.799 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:949245ad36:node2:switch_dimmer to 100 [PercentType]
2021-03-17 15:45:49.800 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:switch_dimmer, cmdClass=COMMAND_CLASS_BASIC, endpoint=0
2021-03-17 15:45:49.800 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Checking channel=zwave:device:949245ad36:node2:scene_number, cmdClass=COMMAND_CLASS_SCENE_ACTIVATION, endpoint=0
2021-03-17 15:45:49.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2021-03-17 15:45:49.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@34f3bc8d.
2021-03-17 15:45:49.802 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction 121  ApplicationCommandHandler.
2021-03-17 15:45:49.803 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : state >> WAIT_DATA
2021-03-17 15:45:49.803 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : node  >> 2
2021-03-17 15:45:49.804 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : class >> 38 == 38.
2021-03-17 15:45:49.804 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking transaction : commd >> 3 == 3.
2021-03-17 15:45:49.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@34f3bc8d.
2021-03-17 15:45:49.805 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance ST: WAIT_DATA
2021-03-17 15:45:49.806 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance WT: ApplicationCommandHandler {}
2021-03-17 15:45:49.806 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RX: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 05 26 03 63 63 00 D2 00
2021-03-17 15:45:49.807 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance TO: DONE
2021-03-17 15:45:49.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: notifyTransactionResponse TID:121 DONE
2021-03-17 15:45:49.808 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2021-03-17 15:45:49.809 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-03-17 15:45:49.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2021-03-17 15:45:49.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2021-03-17 15:45:49.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-17 15:45:49.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-17 15:45:49.811 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2021-03-17 15:45:49.811 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer

So maybe the issue is not with the HAIL command, but with the event listener / command handler…?

schalli · March 18, 2021, 4:24am

Update:
Even after rebooting the server, OH was not polling the dimmers after operating them.
OH receives a hail command, but doesn’t poll the status.
Only after modifying the channel link, OH was polling and updating the status again.
Very weird…

schalli · March 28, 2021, 4:29am

PS: I’m using openHAB 3.0.1

Bruce_Osborne · March 28, 2021, 1:52pm

That device has not been modified since 2.5.0.Perhaps the log viewer can help.

schalli · March 28, 2021, 6:19pm

Hi Bruce,

I haven’t tried OH2.5 with these devices.
Above, you can find logs where the controller polls the device after getting hailed, and where the controller did not respond to the hail command.
Is there some more detailed logging I should turn on to investigate, why the controller ignored the hail command?

Thanks,
Daniel

Bruce_Osborne · March 28, 2021, 6:24pm

@chris could best answer that question.

system · May 9, 2021, 10:24am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.