HS1HT-Z Temperature/Humidity Sensor NaN

  • Platform information:
    • Hardware:
      Raspberry Pi 2 Model B Rev 1.1
      USB Z-wave+ controller everspring
  • OS: Raspbian GNU/Linux 10 (buster)
    • Java Runtime Environment: OpenJDK Runtime Environment (build 1.8.0_212-8u212-b01-1+rpi1-b01)
    • openHAB version: 2.5.0.M6

Hello OpenHab community,
This is my second attempt to use a Zwave device with OpenHab but I am still unsuccessful ;-(
I bought this temperature sensor:
https://www.aliexpress.com/snapshot/0.html?spm=a2g0s.buyer_leave_review.0.0.e61b6c1bQu1KKS&orderId=3001131433855308&productId=32814390727

I was able to find and add the thing.
It is reported as:

Z-Wave Node 008: HS1HT-Z Temperature/Humidity Sensor

The issue is that the temperature and humidity are reported as -NaN in the paper UI.
Is it my device which is not working properly or did I miss something in the configuration?

Thank for your help;
Alexandre

07:20:37.526 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 576 to 577
07:20:37.532 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=15, payload=0F 23 
07:20:37.536 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=15, payload=0F 23 
07:20:37.540 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 15
07:20:37.542 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
07:20:37.545 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 15
07:20:37.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 529: (Callback 15)
07:20:37.550 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
07:20:37.553 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 529: callback 15
07:20:37.560 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=15, payload=0F 23 
07:20:37.562 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
07:20:37.565 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
07:20:37.568 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 529: Transaction CANCELLED
07:20:37.571 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 1 attempts left!
07:20:37.576 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 529: Transaction RESET with 1 retries remaining.
07:20:37.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:20:37.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 529 to queue - size 5
07:20:37.584 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:20:37.588 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 10 A3 
07:20:37.596 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 10 A3 
07:20:37.599 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
07:20:37.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
07:20:37.605 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
07:20:37.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:20:37.613 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 562 to 563
07:20:37.614 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 529: Transaction not completed
07:20:37.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:20:37.621 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
07:20:37.624 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
07:20:37.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:20:37.630 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:20:37.641 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 10 23 81 
07:20:37.649 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 577 to 578
07:20:37.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=16, payload=10 23 
07:20:37.657 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=16, payload=10 23 
07:20:37.660 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
07:20:37.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
07:20:37.665 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 529: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 16
07:20:37.667 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 529: (Callback 16)
07:20:37.669 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
07:20:37.671 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 529: callback 16
07:20:37.674 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=16, payload=10 23 
07:20:37.676 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
07:20:37.678 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
07:20:37.680 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 529: Transaction CANCELLED
07:20:37.682 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Retry count exceeded. Discarding message: TID 529: [CANCELLED] priority=Controller, requiresResponse=true, callback: 16
07:20:37.684 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 529: Transaction completed
07:20:37.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:529 CANCELLED
07:20:37.689 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:20:37.689 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 529: Transaction event listener: DONE: CANCELLED -> 
07:20:37.691 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:20:37.696 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@6e67ea
07:29:18.450 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@515384
07:29:18.455 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:29:18.459 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 530 to queue - size 4
07:29:18.462 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:29:18.468 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 11 A2 
07:29:18.475 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 48 01 11 A2 
07:29:18.478 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 530: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 17
07:29:23.482 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 1: TID 530: Timeout at state WAIT_REQUEST. 3 retries remaining.
07:29:23.486 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 530: Transaction is current transaction, so clearing!!!!!
07:29:23.490 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 530: Transaction CANCELLED
07:29:23.494 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:530 CANCELLED
07:29:23.498 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:29:23.498 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 530: Transaction event listener: DONE: CANCELLED -> 
07:29:23.501 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@14538ff
07:48:12.400 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1234683
07:48:12.406 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:48:12.410 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 531 to queue - size 5
07:48:12.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:48:12.422 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 12 A1 
07:48:12.429 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 12 A1 
07:48:12.433 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
07:48:12.437 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
07:48:12.441 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
07:48:12.446 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.451 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.455 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
07:48:12.457 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 563 to 564
07:48:12.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
07:48:12.461 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.465 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:48:12.480 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 12 23 83 
07:48:12.480 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 578 to 579
07:48:12.493 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=18, payload=12 23 
07:48:12.499 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=18, payload=12 23 
07:48:12.502 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
07:48:12.506 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
07:48:12.509 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 18
07:48:12.512 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 531: (Callback 18)
07:48:12.516 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
07:48:12.520 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 531: callback 18
07:48:12.524 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=18, payload=12 23 
07:48:12.528 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
07:48:12.531 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
07:48:12.534 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 531: Transaction CANCELLED
07:48:12.537 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 2 attempts left!
07:48:12.540 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 531: Transaction RESET with 2 retries remaining.
07:48:12.543 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:48:12.546 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 531 to queue - size 5
07:48:12.548 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:48:12.553 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 13 A0 
07:48:12.558 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 13 A0 
07:48:12.561 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
07:48:12.564 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
07:48:12.567 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 531: Transaction not completed
07:48:12.569 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.570 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
07:48:12.572 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:48:12.576 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.578 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 564 to 565
07:48:12.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.583 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
07:48:12.585 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
07:48:12.587 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.590 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:48:12.604 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 13 23 82 
07:48:12.605 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 579 to 580
07:48:12.613 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=19, payload=13 23 
07:48:12.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=19, payload=13 23 
07:48:12.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
07:48:12.622 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
07:48:12.625 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 19
07:48:12.627 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 531: (Callback 19)
07:48:12.629 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
07:48:12.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 531: callback 19
07:48:12.634 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=19, payload=13 23 
07:48:12.637 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
07:48:12.639 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
07:48:12.641 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 531: Transaction CANCELLED
07:48:12.643 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 1 attempts left!
07:48:12.645 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 531: Transaction RESET with 1 retries remaining.
07:48:12.647 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:48:12.650 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 531 to queue - size 5
07:48:12.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:48:12.658 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 14 A7 
07:48:12.663 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 14 A7 
07:48:12.666 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
07:48:12.669 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
07:48:12.672 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 531: Transaction not completed
07:48:12.674 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.674 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
07:48:12.677 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:48:12.680 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
07:48:12.684 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 565 to 566
07:48:12.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
07:48:12.688 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
07:48:12.696 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.698 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
07:48:12.708 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 14 23 85 
07:48:12.717 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 580 to 581
07:48:12.719 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=20, payload=14 23 
07:48:12.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=20, payload=14 23 
07:48:12.727 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
07:48:12.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
07:48:12.732 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 531: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 20
07:48:12.734 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 531: (Callback 20)
07:48:12.737 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
07:48:12.739 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 531: callback 20
07:48:12.743 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=20, payload=14 23 
07:48:12.746 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
07:48:12.748 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
07:48:12.751 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 531: Transaction CANCELLED
07:48:12.754 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Retry count exceeded. Discarding message: TID 531: [CANCELLED] priority=Controller, requiresResponse=true, callback: 20
07:48:12.756 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 531: Transaction completed
07:48:12.759 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:531 CANCELLED
07:48:12.762 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
07:48:12.762 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 531: Transaction event listener: DONE: CANCELLED -> 
07:48:12.764 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:48:12.768 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1e8fd5b
07:48:20.506 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...
07:48:20.510 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling deferred until initialisation complete
07:56:28.406 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@515384
07:56:28.411 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
07:56:28.415 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 532 to queue - size 4
07:56:28.418 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:56:28.425 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 15 A6 
07:56:28.431 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 48 01 15 A6 
07:56:28.433 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 532: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 21
07:56:33.437 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 1: TID 532: Timeout at state WAIT_REQUEST. 3 retries remaining.
07:56:33.440 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 532: Transaction is current transaction, so clearing!!!!!
07:56:33.442 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 532: Transaction CANCELLED
07:56:33.446 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:532 CANCELLED
07:56:33.451 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 532: Transaction event listener: DONE: CANCELLED -> 
07:56:33.451 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
07:56:33.461 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7747f1
08:15:47.473 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1234683
08:15:47.481 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
08:15:47.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 533 to queue - size 5
08:15:47.488 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:15:47.495 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 16 A5 
08:15:47.503 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 16 A5 
08:15:47.507 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
08:15:47.512 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 22
08:15:47.521 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
08:15:47.526 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.529 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 566 to 567
08:15:47.531 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.534 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 22
08:15:47.538 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
08:15:47.541 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.545 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
08:15:47.559 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 16 23 87 
08:15:47.559 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 581 to 582
08:15:47.569 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=22, payload=16 23 
08:15:47.573 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=22, payload=16 23 
08:15:47.576 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 22
08:15:47.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
08:15:47.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 22
08:15:47.584 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 533: (Callback 22)
08:15:47.587 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
08:15:47.590 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 533: callback 22
08:15:47.594 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=22, payload=16 23 
08:15:47.597 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
08:15:47.600 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
08:15:47.602 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 533: Transaction CANCELLED
08:15:47.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 2 attempts left!
08:15:47.608 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 533: Transaction RESET with 2 retries remaining.
08:15:47.610 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
08:15:47.613 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 533 to queue - size 5
08:15:47.616 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:15:47.621 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 17 A4 
08:15:47.626 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 17 A4 
08:15:47.629 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
08:15:47.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 23
08:15:47.634 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
08:15:47.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 533: Transaction not completed
08:15:47.637 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.639 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.640 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
08:15:47.643 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.645 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 567 to 568
08:15:47.646 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 23
08:15:47.648 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
08:15:47.650 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
08:15:47.669 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 17 23 86 
08:15:47.672 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 582 to 583
08:15:47.676 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=23, payload=17 23 
08:15:47.679 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=23, payload=17 23 
08:15:47.681 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 23
08:15:47.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
08:15:47.685 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 23
08:15:47.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 533: (Callback 23)
08:15:47.689 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
08:15:47.691 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 533: callback 23
08:15:47.694 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=23, payload=17 23 
08:15:47.696 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
08:15:47.698 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
08:15:47.701 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 533: Transaction CANCELLED
08:15:47.703 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 1 attempts left!
08:15:47.706 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 533: Transaction RESET with 1 retries remaining.
08:15:47.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
08:15:47.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 533 to queue - size 5
08:15:47.714 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:15:47.720 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 18 AB 
08:15:47.725 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 18 AB 
08:15:47.728 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
08:15:47.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 24
08:15:47.732 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
08:15:47.733 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 533: Transaction not completed
08:15:47.736 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.736 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.740 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
08:15:47.741 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_ack changed from 568 to 569
08:15:47.743 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
08:15:47.746 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 24
08:15:47.749 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
08:15:47.751 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.754 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
08:15:47.768 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 18 23 89 
08:15:47.777 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_5dcd321b_serial_sof changed from 583 to 584
08:15:47.778 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=24, payload=18 23 
08:15:47.782 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=24, payload=18 23 
08:15:47.785 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 24
08:15:47.788 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
08:15:47.790 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 533: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 24
08:15:47.793 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 533: (Callback 24)
08:15:47.796 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
08:15:47.798 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 533: callback 24
08:15:47.801 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=24, payload=18 23 
08:15:47.803 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
08:15:47.805 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
08:15:47.807 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 533: Transaction CANCELLED
08:15:47.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Retry count exceeded. Discarding message: TID 533: [CANCELLED] priority=Controller, requiresResponse=true, callback: 24
08:15:47.812 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 533: Transaction completed
08:15:47.815 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:533 CANCELLED
08:15:47.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
08:15:47.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 533: Transaction event listener: DONE: CANCELLED -> 
08:15:47.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:15:47.822 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@13b0285
08:18:20.506 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...
08:18:20.510 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling deferred until initialisation complete
08:23:38.366 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@515384
08:23:38.371 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
08:23:38.374 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 534 to queue - size 4
08:23:38.377 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:23:38.384 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 19 AA 
08:23:38.390 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 05 00 48 01 19 AA 
08:23:38.393 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 534: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 25
08:23:43.397 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 1: TID 534: Timeout at state WAIT_REQUEST. 3 retries remaining.
08:23:43.402 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 534: Transaction is current transaction, so clearing!!!!!
08:23:43.408 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 534: Transaction CANCELLED
08:23:43.411 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:534 CANCELLED
08:23:43.416 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
08:23:43.416 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 534: Transaction event listener: DONE: CANCELLED -> 
08:23:43.423 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d46408

First thing, please use code fences when pasting logs:

Second thing is: your device does not respond:

Is the device online?
Which channels did you link to which items?
Which zwave binding version are you using?

Here are the correct channels and items you need to use:
https://www.openhab.org/addons/bindings/zwave/thing.html?manufacturer=heiman&file=hs1htz_0_0.html

Put them on a sitemap and watch BasicUI. NaN usually means the device is not sending any data yet. You may need to wake it up several times.

1 Like

:+1: I’ve edited the post above to make this more readable.

2 Likes

Sorry the pasting logs.
As you can see in the attached, screenshot, the device is indcated as ONLINE.

The version of the Zwave binding is “binding-zwave - 2.5.0.M6”

I am trying to play with the different options.

10:48:20.506 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...
10:48:20.510 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling deferred until initialisation complete
10:49:07.454 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update received
10:49:07.468 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored action_heal to false (Boolean)
10:49:07.472 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored binding_cmdrepollperiod to 1500 (BigDecimal)
10:49:07.476 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update set wakeup_node to 1 (BigDecimal)
10:49:07.480 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Set wakeup node to '1'
10:49:07.484 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored action_failed to false (Boolean)
10:49:07.488 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored wakeup_interval to 0 (BigDecimal)
10:49:07.492 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored action_remove to false (Boolean)
10:49:07.497 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored group_1 to null (null)
10:49:07.501 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored binding_pollperiod to 86400 (BigDecimal)
10:49:07.505 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored group_3 to null (null)
10:49:07.510 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored node_id to 8 (BigDecimal)
10:49:07.514 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored group_2 to null (null)
10:49:07.536 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:sensor_temperature unlinked - polling stopped.
10:49:07.541 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:sensor_relhumidity unlinked - polling stopped.
10:49:07.548 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:battery-level unlinked - polling stopped.
10:49:07.570 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:sensor_temperature linked - polling started.
10:49:07.583 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:sensor_relhumidity linked - polling started.
10:49:07.602 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:5dcd321b:node8:battery-level linked - polling started.
10:49:07.616 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:5dcd321b:node8' has been updated.
10:49:07.619 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Wakeup interval not specified, using 3600
10:49:07.626 [INFO ] [smarthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=wakeup_node, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]
10:49:07.631 [DEBUG] [.commandclass.ZWaveWakeUpCommandClass] - NODE 8: Creating new message for command WAKE_UP_INTERVAL_SET to 3600s, node 1
10:49:07.637 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY NOT required on COMMAND_CLASS_WAKE_UP
10:49:07.641 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 8: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
10:49:07.645 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Bump transaction 545 priority from Config to Immediate
10:49:07.648 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue
10:49:07.656 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Added 545 to queue - size 5
10:49:07.662 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:49:07.667 [DEBUG] [.commandclass.ZWaveWakeUpCommandClass] - NODE 8: Creating new message for application command WAKE_UP_INTERVAL_GET
10:49:07.671 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 8: SECURITY NOT required on COMMAND_CLASS_WAKE_UP
10:49:07.675 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 8: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
10:49:07.680 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Bump transaction 546 priority from Config to Immediate
10:49:07.685 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Adding to device queue
10:49:07.691 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 8: Added 546 to queue - size 6
10:49:07.695 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Remember that Thing status does not tell you that the device is online, only that the expected pathway for openHAB to attempt to communicate with it appears to be okay. e.g. the zwave dongle is alive and the device address looks valid.

Thanks for the information, I did not know.
I am seeing 3 nodes


When I am trying to change the association groups to controller, I can see

13:28:10.519 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Association 3 consolidated to [controller]
13:28:10.523 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Unknown association group 3
13:28:10.528 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update ignored node_id to 8 (BigDecimal)
13:28:10.533 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Configuration update set group_2 to [controller] (ArrayList)
13:28:10.538 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Association 2 consolidated to [controller]
13:28:10.542 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 8: Unknown association group 2

Hi,
As far as I understand, this device is off almost all the time in order to save its battery.
It is reporting its status (temperature, humidity and battery level) only when it is waking up.
It could explain why it is not responding to the polling.
I could read that the device is waking up every 300s but I don’t see anything in the logs.
There is no button to force a wake up. In the documentation, it is written that we can only include/exclude or factory reset the device.
At the moment, I am stuck, I don’t know how to progress further.
Any help is really appreciated :wink:

First thing, make sure ONLY the Lifeline association group is set to your controller.
If that does not help exclude, factory reset, include.

Hi Sihui,
Thanks for your help.
I will try tonight.
Do you know why I have this “NODE 9: Unknown association group 1” message?
Is it an error or just a warning I can ignore?

12:35:16.078 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set group_1 to controller (String)
12:35:16.083 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Association 1 consolidated to [controller]
12:35:16.087 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Unknown association group 1

The binding will not poll the device if it is not awake, so this should not be an issue.

My guess is that the device is probably not initialised properly - ie the binding has not completed the interrogation phase which requires the device to be awake for a while after the inclusion.

I excluded and included the device again.
This is the new log:

13:00:31.634 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:0696af2c
13:00:31.639 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
13:00:31.646 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:0696af2c
13:00:31.649 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
13:00:31.654 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
13:00:31.657 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller start inclusion
13:00:31.664 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
13:00:31.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 87 to queue - size 1
13:00:31.670 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:31.675 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 9D EC
13:00:31.679 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 9D EC
13:00:31.683 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:00:31.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 87: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 157
13:00:31.689 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:00:31.703 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:31.707 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:31.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 87: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 157
13:00:31.710 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:00:31.712 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:31.714 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:00:31.715 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 9D 01 00 00 2E
13:00:31.727 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 172 to 173
13:00:31.729 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 223 to 224
13:00:31.733 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=157, payload=9D 01 00 00
13:00:31.738 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=157, payload=9D 01 00 00
13:00:31.740 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 87: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 157
13:00:31.741 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:00:31.743 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 87: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 157
13:00:31.745 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 87: (Callback 157)
13:00:31.747 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:00:31.749 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 87: callback 157
13:00:31.751 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=157, payload=9D 01 00 00
13:00:31.753 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
13:00:31.757 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
13:00:31.759 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 87: Transaction COMPLETED
13:00:31.761 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 75ms
13:00:31.763 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 87: Transaction completed
13:00:31.764 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:87 DONE
13:00:31.766 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:31.767 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:33.700 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
13:00:33.726 [WARN ] [zwave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! Manufacturer data not known.
13:00:33.758 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery completed
13:00:33.782 [WARN ] [zwave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery could not resolve to a thingType! Manufacturer data not known.
13:00:33.799 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery completed
13:00:33.820 [WARN ] [zwave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery could not resolve to a thingType! Manufacturer data not known.
13:00:33.872 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery completed
13:00:33.885 [WARN ] [zwave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery could not resolve to a thingType! Manufacturer data not known.
13:00:33.900 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery completed
13:00:33.910 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery resolved to thingType zwave:heiman_hs1htz_00_000
13:00:33.932 [INFO ] [smarthome.event.InboxAddedEvent      ] - Discovery Result with UID 'zwave:device:0696af2c:node9' has been added.
13:00:33.930 [INFO ] [ig.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:0696af2c:node9' to inbox.
13:00:34.585 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 224 to 225
13:00:34.588 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 4A 9D 02 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 4C
13:00:34.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=157, payload=9D 02 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.610 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=157, payload=9D 02 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:00:34.618 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:00:34.620 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 225 to 226
13:00:34.623 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:00:34.624 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 4A 9D 03 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 4D
13:00:34.627 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=157, payload=9D 02 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.630 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: New node found.
13:00:34.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:34.634 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:34.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=157, payload=9D 03 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.644 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=157, payload=9D 03 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.646 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:00:34.647 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:00:34.649 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:00:34.652 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=3, callback=157, payload=9D 03 09 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31
13:00:34.655 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 9: Adding slave.
13:00:34.657 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeSlaveFound
13:00:34.662 [DEBUG] [nal.protocol.ZWaveInclusionController] - NODE 9: Including node.
13:00:34.665 [DEBUG] [nal.protocol.ZWaveInclusionController] - NODE 9: Newly included node already exists - not initialising.
13:00:34.666 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:34.667 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:34.987 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 9D 05 09 00 23
13:00:34.990 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 226 to 227
13:00:34.994 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=157, payload=9D 05 09 00
13:00:34.997 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=157, payload=9D 05 09 00
13:00:34.998 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:00:35.000 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:00:35.001 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:00:35.003 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=157, payload=9D 05 09 00
13:00:35.004 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 9: Add Node: Protocol done.
13:00:35.006 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSlaveFound, new event IncludeProtocolDone
13:00:35.007 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
13:00:35.009 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 88 to queue - size 1
13:00:35.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:35.012 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 9E 2B
13:00:35.014 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 9E 2B
13:00:35.015 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:00:35.017 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 88: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 158
13:00:35.019 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion protocol completed with nodeId == 0! Nothing to do!
13:00:35.020 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:35.022 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:00:35.024 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:00:35.027 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 173 to 174
13:00:35.028 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:35.032 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:35.035 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 88: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 158
13:00:35.036 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:00:35.038 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:35.040 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:00:35.073 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 9E 06 09 00 23
13:00:35.076 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 227 to 228
13:00:35.079 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=158, payload=9E 06 09 00
13:00:35.082 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=158, payload=9E 06 09 00
13:00:35.084 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 88: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 158
13:00:35.086 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:00:35.088 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 88: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 158
13:00:35.089 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 88: (Callback 158)
13:00:35.090 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:00:35.092 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 88: callback 158
13:00:35.093 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=158, payload=9E 06 09 00
13:00:35.095 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Done.
13:00:35.098 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovered
13:00:35.108 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeProtocolDone, new event IncludeDone
13:00:35.110 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
13:00:35.112 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 89 to queue - size 1
13:00:35.114 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:00:35.117 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
13:00:35.119 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
13:00:35.122 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 88: Advanced to DONE
13:00:35.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 106ms
13:00:35.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 88: Transaction completed
13:00:35.127 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:88 DONE
13:00:35.129 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:35.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:35.132 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
13:00:35.134 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
13:00:35.136 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:00:35.142 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 89: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
13:00:35.140 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:00:35.147 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:35.149 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:00:35.149 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 174 to 175
13:00:35.151 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 89: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
13:00:35.153 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:00:35.155 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:00:35.156 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:00:40.146 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 89: Timeout at state WAIT_REQUEST. 3 retries remaining.
13:00:40.148 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 89: Transaction is current transaction, so clearing!!!!!
13:00:40.150 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 89: Transaction CANCELLED
13:00:40.152 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:89 CANCELLED
13:00:40.155 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:43.604 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zwave:device:0696af2c:node9' has been removed.
13:00:43.660 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:0696af2c:node9' changed from UNINITIALIZED to INITIALIZING
13:00:43.707 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:0696af2c:node9.
13:00:43.815 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:0696af2c:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
13:00:43.818 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller status changed to ONLINE.
13:00:43.820 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller is ONLINE. Starting device initialisation.
13:00:43.831 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:0696af2c:node9' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
13:00:43.870 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating node properties.
13:00:43.872 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating node properties. MAN=608
13:00:43.875 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating node properties. MAN=608. SET. Was null
13:00:43.876 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node9' has been updated.
13:00:43.878 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Properties synchronised
13:00:43.893 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration synchronised
13:00:43.896 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node9' has been updated.
13:00:43.919 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
13:00:43.921 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node9' has been updated.
13:00:43.921 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising Thing Node...
13:00:43.924 [INFO ] [smarthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
13:00:43.924 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising cmd channel zwave:device:0696af2c:node9:sensor_temperature for QuantityType
13:00:43.926 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising state channel zwave:device:0696af2c:node9:sensor_temperature for QuantityType
13:00:43.929 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising state channel zwave:device:0696af2c:node9:sensor_temperature for QuantityType
13:00:43.931 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising cmd channel zwave:device:0696af2c:node9:sensor_relhumidity for DecimalType
13:00:43.933 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising state channel zwave:device:0696af2c:node9:sensor_relhumidity for DecimalType
13:00:43.936 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising state channel zwave:device:0696af2c:node9:sensor_relhumidity for DecimalType
13:00:43.939 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising cmd channel zwave:device:0696af2c:node9:battery-level for PercentType
13:00:43.941 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising state channel zwave:device:0696af2c:node9:battery-level for PercentType
13:00:43.944 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling initialised at 1800 seconds - start in 1215000 milliseconds.
13:00:43.946 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Device initialisation complete.
13:00:50.675 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
13:00:54.293 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update received
13:00:54.305 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set action_heal to false (Boolean)
13:00:54.308 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set binding_cmdrepollperiod to 1500 (BigDecimal)
13:00:54.312 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set wakeup_node to null (null)
13:00:54.315 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Error converting wakeup value null
13:00:54.318 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set action_failed to false (Boolean)
13:00:54.321 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update ignored wakeup_interval to 86400 (BigDecimal)
13:00:54.325 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set group_1 to controller (String)
13:00:54.328 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Association 1 consolidated to [controller]
13:00:54.334 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Current members before update ZWaveAssociationGroup [index=1, name=Lifeline, profile1=0, profile2=1, associations=[]]
13:00:54.339 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Members after config update ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1_1]]
13:00:54.344 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Controller is master - forcing associations
13:00:54.390 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Group is controller - forcing association
13:00:54.394 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Members after controller update ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1_1]]
13:00:54.397 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Adding node_1_1 to association group 1
13:00:54.401 [DEBUG] [andclass.ZWaveAssociationCommandClass] - NODE 9: Creating new message for application command ASSOCIATIONCMD_SET, group=1, node=1
13:00:54.405 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY not supported
13:00:54.408 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 9: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
13:00:54.411 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Bump transaction 90 priority from Config to Immediate
13:00:54.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Adding to device queue
13:00:54.417 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Added 90 to queue - size 6
13:00:54.421 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:54.424 [DEBUG] [andclass.ZWaveAssociationCommandClass] - NODE 9: Creating new message for application command ASSOCIATIONCMD_GET group 1
13:00:54.428 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 9: SECURITY not supported
13:00:54.430 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 9: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
13:00:54.434 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Bump transaction 91 priority from Config to Immediate
13:00:54.436 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Adding to device queue
13:00:54.440 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 9: Added 91 to queue - size 7
13:00:54.443 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:00:54.446 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set action_remove to false (Boolean)
13:00:54.449 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update ignored group_3 to null (null)
13:00:54.452 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update set binding_pollperiod to 86400 (BigDecimal)
13:00:54.457 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Polling initialised at 86400 seconds - start in 8121600 milliseconds.
13:00:54.460 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update ignored node_id to 9 (BigDecimal)
13:00:54.462 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 9: Configuration update ignored group_2 to null (null)
13:00:54.481 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node9' has been updated.
13:00:54.486 [INFO ] [smarthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[ConfigStatusMessage [parameterName=group_1, type=PENDING, messageKey=null, arguments=null, message=null, statusCode=null]]]
13:01:31.645 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:0696af2c
13:01:31.648 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
13:01:42.397 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@780f1c
13:01:42.406 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
13:01:42.408 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 92 to queue - size 8
13:01:42.410 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:01:42.413 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 A0 13
13:01:42.416 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 A0 13
13:01:42.418 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:01:42.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 160
13:01:42.423 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:01:42.426 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.429 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.431 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 160
13:01:42.433 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:01:42.435 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.436 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:01:42.438 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 175 to 176
13:01:42.457 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 A0 23 31
13:01:42.462 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=160, payload=A0 23
13:01:42.464 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=160, payload=A0 23
13:01:42.465 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 228 to 229
13:01:42.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 160
13:01:42.469 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:01:42.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 160
13:01:42.472 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 92: (Callback 160)
13:01:42.475 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:01:42.477 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 92: callback 160
13:01:42.479 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=160, payload=A0 23
13:01:42.481 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
13:01:42.483 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
13:01:42.485 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 92: Transaction CANCELLED
13:01:42.486 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 2 attempts left!
13:01:42.488 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 92: Transaction RESET with 2 retries remaining.
13:01:42.489 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
13:01:42.491 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 92 to queue - size 8
13:01:42.492 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:01:42.495 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 A1 12
13:01:42.498 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 A1 12
13:01:42.500 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:01:42.501 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 161
13:01:42.503 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:01:42.504 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 92: Transaction not completed
13:01:42.505 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.506 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.507 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:01:42.509 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.511 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 161
13:01:42.512 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 176 to 177
13:01:42.512 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:01:42.513 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.515 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:01:42.538 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 A1 23 30
13:01:42.542 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=161, payload=A1 23
13:01:42.544 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 229 to 230
13:01:42.546 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=161, payload=A1 23
13:01:42.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 161
13:01:42.549 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:01:42.550 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 161
13:01:42.552 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 92: (Callback 161)
13:01:42.553 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:01:42.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 92: callback 161
13:01:42.556 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=161, payload=A1 23
13:01:42.558 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
13:01:42.559 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
13:01:42.560 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 92: Transaction CANCELLED
13:01:42.561 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: CANCEL while sending message. Requeueing - 1 attempts left!
13:01:42.562 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 92: Transaction RESET with 1 retries remaining.
13:01:42.564 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
13:01:42.565 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Added 92 to queue - size 8
13:01:42.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:01:42.568 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 01 A2 11
13:01:42.570 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 A2 11
13:01:42.571 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:01:42.573 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 162
13:01:42.574 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:01:42.574 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 92: Transaction not completed
13:01:42.576 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.577 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:01:42.577 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:01:42.581 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 162
13:01:42.581 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 177 to 178
13:01:42.582 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:01:42.584 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.585 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:01:42.609 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 A2 23 33
13:01:42.613 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=162, payload=A2 23
13:01:42.616 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=162, payload=A2 23
13:01:42.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 162
13:01:42.618 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 230 to 231
13:01:42.619 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:01:42.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 92: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 162
13:01:42.622 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 92: (Callback 162)
13:01:42.624 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:01:42.626 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 92: callback 162
13:01:42.628 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=162, payload=A2 23
13:01:42.630 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: Got NodeNeighborUpdate request.
13:01:42.631 [DEBUG] [RequestNodeNeighborUpdateMessageClass] - NODE 1: NodeNeighborUpdate FAILED
13:01:42.632 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 92: Transaction CANCELLED
13:01:42.634 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: Retry count exceeded. Discarding message: TID 92: [CANCELLED] priority=Controller, requiresResponse=true, callback: 162
13:01:42.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: TID 92: Transaction completed
13:01:42.636 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:92 CANCELLED
13:01:42.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:01:42.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 92: Transaction event listener: DONE: CANCELLED ->
13:01:42.639 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:01:42.640 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@96e8fa

More logs
The device is NODE 10.
It seems to wake up when I am pressing the button 3 times and it is blinking twice.
I can see exchanges.

13:27:50.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 125: (Callback 179)
13:27:50.428 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:27:50.430 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 125: callback 179
13:27:50.432 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=179, payload=B3 01 
13:27:50.435 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 179, Status = Transmission complete, no ACK received(1)
13:27:50.437 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 125: Transaction CANCELLED
13:27:50.439 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:27:50.442 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Transaction failed waiting for REQUEST, assume sleeping device.
13:27:50.444 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: CANCEL while sending message. Requeueing - 2 attempts left!
13:27:50.446 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 125: Transaction RESET with 2 retries remaining.
13:27:50.448 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
13:27:50.450 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 125 to queue - size 6
13:27:50.452 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:27:50.456 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 125: Transaction not completed
13:27:50.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:27:50.460 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:27:53.988 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 285 to 286
13:27:53.990 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 58 
13:27:54.002 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:27:54.007 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:27:54.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:27:54.012 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:27:54.015 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:27:54.019 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:27:54.022 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update request. Node information received. Transaction null
13:27:54.024 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE
13:27:54.026 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SECURITY_2
13:27:54.028 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SUPERVISION
13:27:54.030 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update - no transaction.
13:27:54.032 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:27:54.035 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:27:54.283 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Is awake with 2 messages in the queue
13:27:54.286 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Start sleep timer at 5000ms
13:27:54.288 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveNodeStatusEvent
13:27:54.314 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 10: Node Status event - Node is AWAKE
13:27:54.329 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node10' has been updated.
13:28:34.007 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 286 to 287
13:28:34.013 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 58 
13:28:34.046 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:28:34.054 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:28:34.060 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:28:34.061 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:28:34.063 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:28:34.068 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:28:34.070 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update request. Node information received. Transaction null
13:28:34.072 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE
13:28:34.073 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SECURITY_2
13:28:34.075 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SUPERVISION
13:28:34.076 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update - no transaction.
13:28:34.078 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.080 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:28:34.084 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 86 13 98 25 B4 73 
13:28:34.088 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 86 13 98 25 B4 73 
13:28:34.090 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:28:34.092 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 125: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.101 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 208 to 209
13:28:34.094 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:28:34.107 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:28:34.109 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:28:34.111 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.113 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:28:34.115 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.117 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:28:34.117 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
13:28:34.119 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 287 to 288
13:28:34.123 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.128 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.130 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:28:34.134 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 125: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.135 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 B4 00 5D 
13:28:34.136 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.138 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
13:28:34.138 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 288 to 289
13:28:34.140 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 125: Advanced to WAIT_REQUEST
13:28:34.143 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 125: Transaction not completed
13:28:34.143 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=180, payload=B4 00 
13:28:34.145 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.147 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:28:34.154 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=180, payload=B4 00 
13:28:34.156 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 0A 04 86 14 98 00 F5 
13:28:34.156 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 289 to 290
13:28:34.160 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 125: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.163 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:28:34.166 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 125: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 180
13:28:34.169 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 04 86 14 98 00 
13:28:34.170 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 125: (Callback 180)
13:28:34.173 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:28:34.175 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 125: callback 180
13:28:34.179 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=180, payload=B4 00 
13:28:34.182 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 180, Status = Transmission complete and ACK received(0)
13:28:34.185 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 125: Advanced to WAIT_DATA
13:28:34.188 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 125: Transaction not completed
13:28:34.193 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 04 86 14 98 00 
13:28:34.195 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:28:34.198 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:VERSION)
13:28:34.200 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
13:28:34.203 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY NOT required on COMMAND_CLASS_VERSION
13:28:34.206 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_VERSION V0 VERSION_COMMAND_CLASS_REPORT
13:28:34.208 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Process Version Command Class Report
13:28:34.210 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Requested Command Class = COMMAND_CLASS_SECURITY, Version = 0
13:28:34.212 [INFO ] [commandclass.ZWaveVersionCommandClass] - NODE 10: Command Class COMMAND_CLASS_SECURITY has version 0!
13:28:34.214 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Removed Command Class COMMAND_CLASS_SECURITY
13:28:34.216 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
13:28:34.218 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1de8601.
13:28:34.221 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1de8601.
13:28:34.223 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:125 DONE
13:28:34.226 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 125: Transaction event listener: DONE: DONE -> 
13:28:34.226 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:28:34.229 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
13:28:34.229 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@14266d0
13:28:34.231 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init transaction completed with response COMPLETE
13:28:34.232 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:28:34.232 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer: VERSION - checking COMMAND_CLASS_POWERLEVEL, version is 0
13:28:34.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.234 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer: VERSION - queued   COMMAND_CLASS_POWERLEVEL
13:28:34.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:28:34.235 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_POWERLEVEL
13:28:34.237 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: ZWaveCommandClassTransactionPayload - send to node
13:28:34.238 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 84 08 25 B5 F1 
13:28:34.238 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
13:28:34.239 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
13:28:34.241 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 84 08 25 B5 F1 
13:28:34.241 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@8ea029
13:28:34.243 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Bump transaction 127 priority from Config to Immediate
13:28:34.245 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:28:34.249 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:28:34.248 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 126: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.254 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:28:34.255 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
13:28:34.255 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 209 to 210
13:28:34.257 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 127 to queue - size 5
13:28:34.259 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:28:34.263 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:28:34.265 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
13:28:34.266 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.268 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:28:34.269 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 290 to 291
13:28:34.270 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.272 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:28:34.272 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.276 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.278 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.281 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:28:34.283 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 126: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.285 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:28:34.288 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
13:28:34.290 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 126: Advanced to WAIT_REQUEST
13:28:34.292 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 126: Transaction not completed
13:28:34.294 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.295 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:28:34.335 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 B5 00 5C 
13:28:34.339 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 
13:28:34.342 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 291 to 292
13:28:34.342 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 
13:28:34.344 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 126: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.346 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:28:34.348 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 126: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 181
13:28:34.350 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 126: (Callback 181)
13:28:34.352 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:28:34.354 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 126: callback 181
13:28:34.356 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=181, payload=B5 00 
13:28:34.359 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 181, Status = Transmission complete and ACK received(0)
13:28:34.361 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 126: Transaction COMPLETED
13:28:34.363 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Response processed after 115ms
13:28:34.365 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 126: Transaction completed
13:28:34.367 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:126 DONE
13:28:34.369 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 126: Transaction event listener: DONE: DONE -> 
13:28:34.369 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:28:34.371 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:28:34.372 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Went to sleep COMPLETE
13:28:34.373 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:29:13.496 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 58 
13:29:13.496 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 292 to 293
13:29:13.514 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:29:13.520 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:29:13.530 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:29:13.532 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:29:13.535 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:29:13.541 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:29:13.546 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update request. Node information received. Transaction null
13:29:13.548 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE
13:29:13.551 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SECURITY_2
13:29:13.554 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SUPERVISION
13:29:13.558 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update - no transaction.
13:29:13.561 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:29:13.564 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:29:13.811 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Is awake with 1 messages in the queue
13:29:13.813 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Start sleep timer at 5000ms
13:29:13.815 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveNodeStatusEvent
13:29:13.835 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 10: Node Status event - Node is AWAKE
13:29:13.843 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node10' has been updated.
13:29:16.316 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: WakeupTimerTask 1 Messages waiting, state VERSION
13:29:18.816 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: WakeupTimerTask 1 Messages waiting, state VERSION
13:29:18.820 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: No more messages, go back to sleep
13:29:18.826 [DEBUG] [.commandclass.ZWaveWakeUpCommandClass] - NODE 10: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
13:29:18.830 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
13:29:18.833 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
13:29:18.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@11c4612
13:29:18.840 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Bump transaction 128 priority from Immediate to Immediate
13:29:18.848 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
13:29:18.852 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 128 to queue - size 6
13:29:18.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:29:18.861 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 86 13 73 25 B6 9A 
13:29:18.868 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 86 13 73 25 B6 9A 
13:29:18.872 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:29:18.875 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:29:18.878 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:29:18.883 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
13:29:18.884 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:29:18.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:29:18.890 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 210 to 211
13:29:18.891 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:29:18.892 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:29:18.884 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 182
13:29:18.900 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 293 to 294
13:29:18.896 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:29:18.908 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 182
13:29:18.915 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:29:18.922 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 182
13:29:18.931 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:29:18.938 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
13:29:18.945 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 127: Advanced to WAIT_REQUEST
13:29:18.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 127: Transaction not completed
13:29:18.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:29:18.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:29:22.998 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 B6 01 5E 
13:29:23.004 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 294 to 295
13:29:23.005 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=182, payload=B6 01 
13:29:23.007 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=182, payload=B6 01 
13:29:23.019 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 127: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 182
13:29:23.022 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:29:23.025 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 127: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 182
13:29:23.027 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 127: (Callback 182)
13:29:23.030 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:29:23.032 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 127: callback 182
13:29:23.036 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=182, payload=B6 01 
13:29:23.039 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 182, Status = Transmission complete, no ACK received(1)
13:29:23.042 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 127: Transaction CANCELLED
13:29:23.045 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:29:23.048 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Transaction failed waiting for REQUEST, assume sleeping device.
13:29:23.050 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: CANCEL while sending message. Requeueing - 2 attempts left!
13:29:23.052 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 127: Transaction RESET with 2 retries remaining.
13:29:23.054 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
13:29:23.056 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 127 to queue - size 6
13:29:23.058 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:29:23.061 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 127: Transaction not completed
13:29:23.063 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:29:23.066 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:30:00.320 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 58 
13:30:00.320 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 295 to 296
13:30:00.340 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:00.357 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:00.367 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:30:00.370 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:30:00.375 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:30:00.382 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:00.387 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update request. Node information received. Transaction null
13:30:00.389 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE
13:30:00.393 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SECURITY_2
13:30:00.395 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SUPERVISION
13:30:00.399 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update - no transaction.
13:30:00.401 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:30:00.405 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:30:00.652 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Is awake with 2 messages in the queue
13:30:00.654 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Start sleep timer at 5000ms
13:30:00.657 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveNodeStatusEvent
13:30:00.675 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 10: Node Status event - Node is AWAKE
13:30:00.679 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:0696af2c:node10' has been updated.
13:30:04.826 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 58 
13:30:04.826 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 296 to 297
13:30:04.844 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:04.853 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:04.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:30:04.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
13:30:04.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: null
13:30:04.867 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=10, callback=132, payload=84 0A 11 04 21 01 5E 85 8E 59 55 86 72 5A 73 80 9F 84 6C 31 
13:30:04.871 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update request. Node information received. Transaction null
13:30:04.874 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_TRANSPORT_SERVICE
13:30:04.877 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SECURITY_2
13:30:04.880 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_SUPERVISION
13:30:04.883 [DEBUG] [message.ApplicationUpdateMessageClass] - NODE 10: Application update - no transaction.
13:30:04.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:30:04.892 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:30:04.898 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 86 13 73 25 B7 9B 
13:30:04.903 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 86 13 73 25 B7 9B 
13:30:04.906 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:30:04.909 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:30:04.911 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.912 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:30:04.916 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:30:04.918 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 211 to 212
13:30:04.920 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.921 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
13:30:04.923 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:30:04.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:30:04.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:30:04.932 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:30:04.937 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:30:04.938 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 B7 00 5E 
13:30:04.940 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.944 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:30:04.947 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 297 to 298
13:30:04.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 127: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.951 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
13:30:04.951 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 298 to 299
13:30:04.954 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=183, payload=B7 00 
13:30:04.955 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
13:30:04.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 127: Advanced to WAIT_REQUEST
13:30:04.963 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 0A 04 86 14 73 01 1F 
13:30:04.964 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 127: Transaction not completed
13:30:04.967 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=183, payload=B7 00 
13:30:04.968 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_sof changed from 299 to 300
13:30:04.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 127: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.973 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 04 86 14 73 01 
13:30:04.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:30:04.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 127: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 183
13:30:04.982 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 127: (Callback 183)
13:30:04.986 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:30:04.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 127: callback 183
13:30:04.993 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=183, payload=B7 00 
13:30:04.996 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 183, Status = Transmission complete and ACK received(0)
13:30:05.001 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 127: Advanced to WAIT_DATA
13:30:05.004 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 127: Transaction not completed
13:30:05.008 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 04 86 14 73 01 
13:30:05.011 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:30:05.014 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:VERSION)
13:30:05.018 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
13:30:05.020 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
13:30:05.023 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_VERSION V0 VERSION_COMMAND_CLASS_REPORT
13:30:05.026 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Process Version Command Class Report
13:30:05.029 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Requested Command Class = COMMAND_CLASS_POWERLEVEL, Version = 1
13:30:05.031 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Version = 1, version set. Enabling extra functionality.
13:30:05.035 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
13:30:05.037 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ac9a20.
13:30:05.041 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ac9a20.
13:30:05.043 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:127 DONE
13:30:05.047 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 127: Transaction event listener: DONE: DONE -> 
13:30:05.047 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:30:05.050 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
13:30:05.051 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@6cdbd9
13:30:05.053 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init transaction completed with response COMPLETE
13:30:05.054 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
13:30:05.056 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:30:05.056 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer: VERSION - checking COMMAND_CLASS_ASSOCIATION, version is 0
13:30:05.059 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:30:05.059 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: Node advancer: VERSION - queued   COMMAND_CLASS_ASSOCIATION
13:30:05.062 [DEBUG] [commandclass.ZWaveVersionCommandClass] - NODE 10: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_ASSOCIATION
13:30:05.064 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 10: ZWaveCommandClassTransactionPayload - send to node
13:30:05.065 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 84 08 25 B8 FC 
13:30:05.067 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
13:30:05.069 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 84 08 25 B8 FC 
13:30:05.069 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
13:30:05.072 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@10c96d6
13:30:05.074 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:30:05.075 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Bump transaction 129 priority from Config to Immediate
13:30:05.076 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 128: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 184
13:30:05.077 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:30:05.081 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:30:05.084 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
13:30:05.086 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:30:05.088 [INFO ] [smarthome.event.ItemStateChangedEvent] - zwave_serial_zstick_0696af2c_serial_ack changed from 212 to 213
13:30:05.089 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 128: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 184
13:30:05.092 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 129 to queue - size 5
13:30:05.094 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:30:05.095 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:30:05.099 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

It is working now!

I understand how it is working now.
In fact, the device is staying awake a very short time.
So I had to wake it up manually maybe 20 times to complete its configuration.
Yes, the device is really tricky to configure!!!

Thank you all for your great support!
image