Hi all,
Unfortunately I’ve got trouble with a zwave device. I was hoping someone could help me out here… I’ve attached info, problem description, problem solving steps and logs below.
Thanx,
Jesse
OS: Debian GNU/Linux 8.11 (jessie)
openHAB version: 2.4.0
ZWave binding version: 2.4.0
Device: Fibaro Roller Shutter 2 (FGRM222)
Controller: Aeotec Z-Stick Gen5
Background: I updated openhab and the zwave binding to version 2.4 and I removed and rediscovered all the zwave things a couple of days ago. Not sure if this problem is related to the update, I find the timing a bit suspicious though.
Problem: When I send the value ‘0’ (zero) to the ‘blinds_shutter’-channel of the device nothing seems to happen, the blind stays in its previous position. However when I send a value from 1 to 100, the device actually responds by moving the blind to the specified position. Calibrating the actuator seems to work fine as well.
I’ve got multiple of these actuators, all of them behave well, except the one mentioned above.
Steps taken: Healed the device, healed the network, re-calibrated the device, rebooted the device by taking it off the mains, restarted openhab, rebooted the server.
Steps not taken: Excluding, including and/or resetting the device. Resetting the controller. (I was hoping to prevent these steps…)
.
Log while sending ‘0’:
13:54:23.404 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:5321d21a:node3:blinds_shutter --> 0 [PercentType]
13:54:23.426 [TRACE] [ZWaveManufacturerProprietaryConverter] - NODE 3: Converted command '0' to value 0 for channel = zwave:device:5321d21a:node3:blinds_shutter, endpoint = 0.
13:54:23.430 [DEBUG] [anufacturerProprietaryFibaroFgrm222V1] - Creating command message FGRM222_SET version 1
13:54:23.433 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
13:54:23.445 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 764 to queue - size 1
13:54:23.448 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:54:23.461 [TRACE] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == true, frequentlyListening == false, awake == false
13:54:23.465 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
13:54:23.468 [TRACE] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:54:23.473 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request
13:54:23.485 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -105
13:54:23.489 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0F 00 13 03 08 91 01 0F 26 01 02 00 00 25 E0 97
13:54:23.498 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0F 00 13 03 08 91 01 0F 26 01 02 00 00 25 E0 97
13:54:23.503 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:54:23.504 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:54:23.509 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: Transaction Start type SendData
13:54:23.510 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:54:23.521 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 764: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 224
13:54:23.522 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:54:23.526 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
13:54:23.529 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:54:23.528 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:54:23.533 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
13:54:23.536 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:54:23.540 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:54:23.538 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:54:23.553 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:54:23.541 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:54:23.562 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:54:23.558 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:25 CEST 2019 - 2000ms
13:54:23.569 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
13:54:23.572 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 764: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 224
13:54:23.574 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:54:23.580 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:54:23.582 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:54:23.583 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:54:23.595 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:54:23.595 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:23.599 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:54:23.601 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:23.603 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:54:23.600 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:25 CEST 2019 - 1958ms
13:54:23.614 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E0 00 00 05 0E
13:54:23.616 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:23.615 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:23.624 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 764: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 224
13:54:23.623 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:25 CEST 2019 - 1935ms
13:54:23.617 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 E0 00 00 05 0E
13:54:23.633 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = 14
13:54:23.635 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:54:23.633 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:54:23.632 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 1500 milliseconds.
13:54:23.644 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 764: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 224
13:54:23.641 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = E0 00 00 05
13:54:23.648 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:23.649 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:54:23.652 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:54:23.658 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:54:23.656 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:54:23.665 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=224, payload=E0 00 00 05
13:54:23.669 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:54:23.677 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance ST: WAIT_RESPONSE
13:54:23.682 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance WT: null {}
13:54:23.689 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:23.692 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance TO: WAIT_REQUEST
13:54:23.701 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 764: Advanced to WAIT_REQUEST
13:54:23.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 764: Transaction not completed
13:54:23.707 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=224, payload=E0 00 00 05
13:54:23.713 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 764: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 224
13:54:23.723 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:54:23.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 764: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 224
13:54:23.729 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 764: (Callback 224)
13:54:23.739 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:54:23.742 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 764: callback 224
13:54:23.745 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=224, payload=E0 00 00 05
13:54:23.753 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:54:23.757 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:54:23.765 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 224, Status = Transmission complete and ACK received(0)
13:54:23.768 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:54:23.773 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 764: Transaction COMPLETED
13:54:23.782 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance ST: DONE
13:54:23.785 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance WT: null {}
13:54:23.793 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=224, payload=E0 00 00 05
13:54:23.796 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 764: TransactionAdvance TO: DONE
13:54:23.805 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 296ms
13:54:23.808 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 764: Transaction completed
13:54:23.812 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:764 DONE
13:54:23.820 [TRACE] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:54:23.826 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:54:23.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:54:23.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:54:23.840 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:54:23.842 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:25.132 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
13:54:25.136 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:5321d21a:node3:blinds_shutter
13:54:25.139 [DEBUG] [anufacturerProprietaryFibaroFgrm222V1] - Creating command message FGRM222_GET version 1
13:54:25.148 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
13:54:25.152 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 765 to queue - size 1
13:54:25.165 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:54:25.168 [TRACE] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == true, frequentlyListening == false, awake == false
13:54:25.172 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
13:54:25.185 [TRACE] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:54:25.188 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request
13:54:25.192 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -77
13:54:25.202 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 91 02 25 E1 B3
13:54:25.207 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 91 02 25 E1 B3
13:54:25.212 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:54:25.214 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:54:25.215 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:54:25.219 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:54:25.217 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: Transaction Start type SendData
13:54:25.225 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:54:25.225 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:54:25.230 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:54:25.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:54:25.233 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:54:25.231 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 765: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 225
13:54:25.246 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:54:25.245 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:54:25.251 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
13:54:25.249 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_MANUFACTURER_PROPRIETARY
13:54:25.261 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:54:25.263 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
13:54:25.267 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:54:25.269 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:54:25.273 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:54:25.275 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:27 CEST 2019 - 2000ms
13:54:25.283 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:54:25.284 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 765: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 225
13:54:25.289 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:54:25.287 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:25.291 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:54:25.295 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:25.294 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:54:25.305 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E1 00 00 05 0F
13:54:25.299 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:27 CEST 2019 - 1976ms
13:54:25.310 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:25.313 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:27 CEST 2019 - 1962ms
13:54:25.316 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:25.323 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 765: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 225
13:54:25.319 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 E1 00 00 05 0F
13:54:25.333 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = 15
13:54:25.335 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:54:25.338 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:54:25.340 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 765: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 225
13:54:25.346 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:25.345 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = E1 00 00 05
13:54:25.358 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:54:25.361 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:54:25.365 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:54:25.363 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:54:25.369 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=225, payload=E1 00 00 05
13:54:25.381 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:54:25.383 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance ST: WAIT_RESPONSE
13:54:25.387 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance WT: ApplicationCommandHandler {}
13:54:25.389 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:54:25.398 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance TO: WAIT_REQUEST
13:54:25.404 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 765: Advanced to WAIT_REQUEST
13:54:25.407 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 765: Transaction not completed
13:54:25.417 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=225, payload=E1 00 00 05
13:54:25.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 765: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 225
13:54:25.424 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:54:25.430 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 765: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 225
13:54:25.436 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 765: (Callback 225)
13:54:25.441 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:54:25.449 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 765: callback 225
13:54:25.451 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=225, payload=E1 00 00 05
13:54:25.461 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:54:25.464 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:54:25.467 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 225, Status = Transmission complete and ACK received(0)
13:54:25.477 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:54:25.480 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance ST: WAIT_REQUEST
13:54:25.483 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance WT: ApplicationCommandHandler {}
13:54:25.489 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=225, payload=E1 00 00 05
13:54:25.501 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
13:54:25.504 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 765: TransactionAdvance TO: WAIT_DATA
13:54:25.513 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 765: Advanced to WAIT_DATA
13:54:25.515 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 765: Transaction not completed
13:54:25.523 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:54:25.526 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:54:25.537 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:54:25.539 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:54:25.542 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:54:30 CEST 2019 - 4973ms
13:54:30.516 [TRACE] [nsactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
13:54:30.519 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 3: TID 765: Timeout at state WAIT_DATA. 3 retries remaining.
13:54:30.523 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 765: Transaction CANCELLED
13:54:30.526 [TRACE] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:54:30.530 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:54:30.534 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:765 CANCELLED
13:54:30.538 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:54:30.541 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:54:30.545 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
Log while sending not ‘0’:
13:58:48.210 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:5321d21a:node3:blinds_shutter --> 6 [PercentType]
13:58:48.218 [TRACE] [ZWaveManufacturerProprietaryConverter] - NODE 3: Converted command '6' to value 6 for channel = zwave:device:5321d21a:node3:blinds_shutter, endpoint = 0.
13:58:48.223 [DEBUG] [anufacturerProprietaryFibaroFgrm222V1] - Creating command message FGRM222_SET version 1
13:58:48.231 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
13:58:48.235 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 770 to queue - size 1
13:58:48.238 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:58:48.241 [TRACE] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == true, frequentlyListening == false, awake == false
13:58:48.243 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
13:58:48.246 [TRACE] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:58:48.248 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request
13:58:48.251 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -105
13:58:48.253 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0F 00 13 03 08 91 01 0F 26 01 02 06 00 25 E6 97
13:58:48.257 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0F 00 13 03 08 91 01 0F 26 01 02 06 00 25 E6 97
13:58:48.262 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:58:48.263 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:58:48.266 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: Transaction Start type SendData
13:58:48.267 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:58:48.270 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 770: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 230
13:58:48.272 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:58:48.275 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
13:58:48.276 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:58:48.276 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:58:48.281 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:58:48.283 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:58:48.285 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:58:48.287 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:58:48.282 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
13:58:48.289 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:58:48.293 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:58:48.290 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
13:58:48.297 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:50 CEST 2019 - 2000ms
13:58:48.298 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:58:48.301 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 770: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 230
13:58:48.302 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:58:48.305 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:48.306 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:58:48.309 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:50 CEST 2019 - 1989ms
13:58:48.310 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:58:48.313 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 1500 milliseconds.
13:58:48.313 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:58:48.319 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:58:48.315 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:48.321 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:48.323 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:58:48.325 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:50 CEST 2019 - 1972ms
13:58:48.328 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E6 00 00 05 08
13:58:48.328 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:48.331 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 E6 00 00 05 08
13:58:48.332 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 770: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 230
13:58:48.334 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = 8
13:58:48.335 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:58:48.338 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:58:48.339 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 770: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 230
13:58:48.341 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = E6 00 00 05
13:58:48.342 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:48.345 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:58:48.346 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:58:48.349 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:58:48.351 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:58:48.352 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:58:48.353 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05
13:58:48.355 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance ST: WAIT_RESPONSE
13:58:48.359 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance WT: null {}
13:58:48.361 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:48.363 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance TO: WAIT_REQUEST
13:58:48.365 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 770: Advanced to WAIT_REQUEST
13:58:48.367 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 770: Transaction not completed
13:58:48.370 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05
13:58:48.372 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 770: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 230
13:58:48.374 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:58:48.376 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 770: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 230
13:58:48.379 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 770: (Callback 230)
13:58:48.381 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:58:48.383 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 770: callback 230
13:58:48.385 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05
13:58:48.387 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:58:48.389 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:58:48.391 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 230, Status = Transmission complete and ACK received(0)
13:58:48.393 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:58:48.396 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 770: Transaction COMPLETED
13:58:48.398 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance ST: DONE
13:58:48.400 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance WT: null {}
13:58:48.402 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05
13:58:48.404 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 770: TransactionAdvance TO: DONE
13:58:48.406 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 140ms
13:58:48.408 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 770: Transaction completed
13:58:48.410 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:770 DONE
13:58:48.412 [TRACE] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:58:48.417 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:58:48.419 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:58:48.421 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:58:48.424 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:58:48.426 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:49.813 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
13:58:49.816 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:5321d21a:node3:blinds_shutter
13:58:49.820 [DEBUG] [anufacturerProprietaryFibaroFgrm222V1] - Creating command message FGRM222_GET version 1
13:58:49.823 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
13:58:49.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: Added 771 to queue - size 1
13:58:49.828 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:58:49.830 [TRACE] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == true, frequentlyListening == false, awake == false
13:58:49.832 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
13:58:49.834 [TRACE] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
13:58:49.837 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 3: Creating empty message of class = SendData (0x13), type = Request
13:58:49.839 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -75
13:58:49.841 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 91 02 25 E7 B5
13:58:49.844 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 91 02 25 E7 B5
13:58:49.848 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
13:58:49.848 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
13:58:49.850 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
13:58:49.853 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: Transaction Start type SendData
13:58:49.854 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:58:49.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 771: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 231
13:58:49.858 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:58:49.858 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
13:58:49.862 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_MANUFACTURER_PROPRIETARY
13:58:49.865 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
13:58:49.868 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
13:58:49.866 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
13:58:49.869 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
13:58:49.872 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
13:58:49.875 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8
13:58:49.874 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:58:49.878 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:51 CEST 2019 - 1999ms
13:58:49.881 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = -24
13:58:49.883 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 771: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 231
13:58:49.884 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:58:49.887 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:49.888 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01
13:58:49.891 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:51 CEST 2019 - 1986ms
13:58:49.892 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:58:49.895 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:58:49.898 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
13:58:49.898 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:58:49.900 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:49.903 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:49.904 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:51 CEST 2019 - 1973ms
13:58:49.906 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Received SOF
13:58:49.908 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:49.911 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E7 00 00 04 08
13:58:49.911 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 771: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 231
13:58:49.914 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 13 E7 00 00 04 08
13:58:49.915 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:58:49.918 [TRACE] [zwave.internal.protocol.SerialMessage] - Calculated checksum = 8
13:58:49.919 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 771: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 231
13:58:49.921 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
13:58:49.922 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:49.925 [TRACE] [zwave.internal.protocol.SerialMessage] - NODE 0: Message payload = E7 00 00 04
13:58:49.926 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
13:58:49.929 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
13:58:49.933 [TRACE] [ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
13:58:49.933 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
13:58:49.936 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 04
13:58:49.937 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
13:58:49.941 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance ST: WAIT_RESPONSE
13:58:49.942 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance WT: ApplicationCommandHandler {}
13:58:49.944 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
13:58:49.947 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance TO: WAIT_REQUEST
13:58:49.949 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 771: Advanced to WAIT_REQUEST
13:58:49.951 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 771: Transaction not completed
13:58:49.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 04
13:58:49.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 771: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 231
13:58:49.957 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
13:58:49.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 771: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 231
13:58:49.961 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 771: (Callback 231)
13:58:49.963 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
13:58:49.965 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 771: callback 231
13:58:49.967 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 04
13:58:49.969 [TRACE] [ave.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
13:58:49.971 [TRACE] [ol.serialmessage.SendDataMessageClass] - Handle Message Send Data Request
13:58:49.973 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)
13:58:49.975 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
13:58:49.977 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance ST: WAIT_REQUEST
13:58:49.979 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance WT: ApplicationCommandHandler {}
13:58:49.981 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance RX: Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 04
13:58:49.983 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance RQ: RREQ=true, RCLS=ApplicationCommandHandler
13:58:49.985 [TRACE] [ve.internal.protocol.ZWaveTransaction] - TID 771: TransactionAdvance TO: WAIT_DATA
13:58:49.987 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 771: Advanced to WAIT_DATA
13:58:49.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: TID 771: Transaction not completed
13:58:49.991 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
13:58:49.993 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
13:58:49.995 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:58:49.997 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
13:58:49.999 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Apr 28 13:58:54 CEST 2019 - 4990ms
13:58:54.989 [TRACE] [nsactionManager$ZWaveTransactionTimer] - Transaction Timeout.......... 1 outstanding transactions
13:58:54.992 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 3: TID 771: Timeout at state WAIT_DATA. 3 retries remaining.
13:58:54.995 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 771: Transaction CANCELLED
13:58:54.998 [TRACE] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
13:58:55.000 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
13:58:55.002 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:771 CANCELLED
13:58:55.004 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
13:58:55.013 [TRACE] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
13:58:55.015 [TRACE] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer