Z-Wave network looks fine but is not working

I am a bit lost. I have setup a few Z-Wave devices and they all worked perfectly fine until I started expanding the network. In particular I have a double relay switch installed which is recognized and looks healthy in HABmin (the thing itself and the network viewer). Unfortunately it does not switch.
Here is the log:

22:34:29.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SWITCH_BINARY
22:34:29.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
22:34:29.419 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
22:34:29.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
22:34:29.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
22:34:29.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jul 23 22:34:31 CEST 2017 - 1999ms
22:34:29.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
22:34:29.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 248: [WAIT_RESPONSE] requiresResponse=false callback: 183
22:34:29.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
22:34:29.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jul 23 22:34:31 CEST 2017 - 1996ms
22:34:29.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
22:34:29.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
22:34:29.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 248: [WAIT_RESPONSE] requiresResponse=false callback: 183
22:34:29.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
22:34:29.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
22:34:29.431 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
22:34:29.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
22:34:29.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
22:34:29.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
22:34:29.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jul 23 22:34:31 CEST 2017 - 1986ms
22:34:29.436 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
22:34:29.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
22:34:29.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
22:34:29.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
22:34:29.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 248: [WAIT_RESPONSE] requiresResponse=false callback: 183
22:34:29.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
22:34:29.444 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 248: [WAIT_RESPONSE] requiresResponse=false callback: 183
22:34:29.446 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
22:34:29.447 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
22:34:29.448 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance ST: WAIT_RESPONSE
22:34:29.449 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance WT: ApplicationCommandHandler {}
22:34:29.451 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
22:34:29.451 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance TO: WAIT_REQUEST
22:34:29.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 248: Advanced to WAIT_REQUEST
22:34:29.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 248: Transaction not completed
22:34:29.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
22:34:29.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
22:34:29.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
22:34:29.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
22:34:29.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jul 23 22:34:34 CEST 2017 - 4995ms
22:34:33.563 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 B7 01 01 9E C2
22:34:33.567 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
22:34:33.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=183, payload=B7 01 01 9E
22:34:33.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=183, payload=B7 01 01 9E
22:34:33.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=183, payload=B7 01 01 9E
22:34:33.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 248: [WAIT_REQUEST] requiresResponse=false callback: 183
22:34:33.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
22:34:33.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 248: [WAIT_REQUEST] requiresResponse=false callback: 183
22:34:33.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 248: (Callback 183)
22:34:33.577 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
22:34:33.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 248: callback 183
22:34:33.580 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=183, payload=B7 01 01 9E
22:34:33.581 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 183, Status = Transmission complete, no ACK received(1)
22:34:33.582 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: Transaction CANCELLED
22:34:33.583 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance ST: CANCELLED
22:34:33.583 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance WT: ApplicationCommandHandler {}
22:34:33.586 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=183, payload=B7 01 01 9E
22:34:33.587 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 248: TransactionAdvance TO: CANCELLED
22:34:33.588 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
22:34:33.589 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
22:34:33.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 248: Transaction completed
22:34:33.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:248 CANCELLED
22:34:33.593 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
22:34:33.604 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
22:34:33.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
22:34:33.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
22:34:33.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
22:34:33.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
22:34:33.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer

It would be great if someone could help me out.

You’re not still in inclusion mode by any chance? Is the new relay the ONLY zwave device that doesn’t switch? Have you tried excluding a re-including it incase the initial process didn’t complete properly?

EDIT: is this the same zwave relay related to this post that you posted a few days ago?

Yes, it is the same device. I don’t think it still is in inclusion mode because it did switch immediately after inclusion when it was right next to the controller. My feeling is that relaying via other nodes does not work properly but I am too inexperienced to gather anything from the logs.

Just for information, the binding only enabled inclusion for 30 seconds so you’d have to start inclusion, then immediately exit the binding to leave it in inclusion mode.

There’s nothing in the logs about this - routing is performed by the controller and it doesn’t provide information on what routes it uses.

The log looks a bit short to be useful. It doesn’t show the command you’re trying to send from the UI, and it doesn’t show the transmit message that the binding is sending, so I can’t say much unfortunately.

Thank, Chris. I will post a more useful log once I am home. Any tips on how to best do this without the log getting spammed by the other devices?

Here is a new log. Hope this contains the required information:

20:45:42.072 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Light_Garden_Hof' received command ON
20:45:42.074 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:15d5c8767fa:node4:switch_binary2 --> ON
20:45:42.075 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 4: Creating new message for application command SWITCH_BINARY_SET
20:45:42.076 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
20:45:42.076 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, endpoint 2
20:45:42.077 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, instance / endpoint 2
20:45:42.077 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 4: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
20:45:42.078 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
20:45:42.078 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
20:45:42.079 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 4: Creating new message for application command SWITCH_BINARY_GET
20:45:42.079 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_BINARY
20:45:42.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, endpoint 2
20:45:42.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, instance / endpoint 2
20:45:42.080 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 4: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
20:45:42.081 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
20:45:42.081 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
20:45:42.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
20:45:42.082 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added to queue - size 0
20:45:42.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
20:45:42.083 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == true, frequentlyListening == false, awake == false
20:45:42.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
20:45:42.084 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
20:45:42.086 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 04 07 60 0D 01 02 25 01 FF 25 B8 C9
20:45:42.088 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0E 00 13 04 07 60 0D 01 02 25 01 FF 25 B8 C9
20:45:42.089 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
20:45:42.090 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: Transaction Start type SendData
20:45:42.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1281: [WAIT_RESPONSE] requiresResponse=false callback: 184
20:45:42.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
20:45:42.091 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
20:45:42.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
20:45:42.092 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
20:45:42.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:44 CEST 2017 - 2000ms
20:45:42.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1281: [WAIT_RESPONSE] requiresResponse=false callback: 184
20:45:42.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:42.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:42.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:44 CEST 2017 - 1998ms
20:45:42.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
20:45:42.095 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:42.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:42.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1281: [WAIT_RESPONSE] requiresResponse=false callback: 184
20:45:42.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
20:45:42.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added to queue - size 0
20:45:42.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:42.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:45:42.102 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
20:45:42.100 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:45:42.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:45:42.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:42.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:44 CEST 2017 - 1986ms
20:45:42.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:45:42.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:42.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:44 CEST 2017 - 1984ms
20:45:42.107 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
20:45:42.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:42.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:42.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:42.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1281: [WAIT_RESPONSE] requiresResponse=false callback: 184
20:45:42.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
20:45:42.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1281: [WAIT_RESPONSE] requiresResponse=false callback: 184
20:45:42.120 [INFO ] [marthome.event.ItemStateChangedEvent] - Light_Garden_Hof changed from OFF to ON
20:45:42.120 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:42.121 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
20:45:42.122 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance ST: WAIT_RESPONSE
20:45:42.124 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance WT: null {}
20:45:42.125 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:42.126 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance TO: WAIT_REQUEST
20:45:42.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1281: Advanced to WAIT_REQUEST
20:45:42.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 1281: Transaction not completed
20:45:42.128 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:42.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:45:42.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:45:42.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:42.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:47 CEST 2017 - 4996ms
20:45:46.206 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 B8 01 01 9C CF
20:45:46.209 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
20:45:46.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=184, payload=B8 01 01 9C
20:45:46.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=184, payload=B8 01 01 9C
20:45:46.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=184, payload=B8 01 01 9C
20:45:46.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1281: [WAIT_REQUEST] requiresResponse=false callback: 184
20:45:46.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
20:45:46.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1281: [WAIT_REQUEST] requiresResponse=false callback: 184
20:45:46.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 1281: (Callback 184)
20:45:46.224 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
20:45:46.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 1281: callback 184
20:45:46.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=184, payload=B8 01 01 9C
20:45:46.230 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 184, Status = Transmission complete, no ACK received(1)
20:45:46.231 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: Transaction CANCELLED
20:45:46.233 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance ST: CANCELLED
20:45:46.235 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance WT: null {}
20:45:46.237 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=184, payload=B8 01 01 9C
20:45:46.239 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1281: TransactionAdvance TO: CANCELLED
20:45:46.240 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
20:45:46.242 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
20:45:46.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 1281: Transaction completed
20:45:46.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:1281 CANCELLED
20:45:46.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
20:45:46.257 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
20:45:46.259 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:46.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
20:45:46.261 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == true, frequentlyListening == false, awake == false
20:45:46.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
20:45:46.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
20:45:46.263 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 04 06 60 0D 01 02 25 02 25 B9 36
20:45:46.264 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0D 00 13 04 06 60 0D 01 02 25 02 25 B9 36
20:45:46.265 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
20:45:46.265 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: Transaction Start type SendData
20:45:46.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1282: [WAIT_RESPONSE] requiresResponse=false callback: 185
20:45:46.267 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
20:45:46.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SWITCH_BINARY
20:45:46.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:46.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:46.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
20:45:46.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
20:45:46.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:46.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:48 CEST 2017 - 1999ms
20:45:46.271 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1282: [WAIT_RESPONSE] requiresResponse=false callback: 185
20:45:46.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:46.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:48 CEST 2017 - 1998ms
20:45:46.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
20:45:46.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1282: [WAIT_RESPONSE] requiresResponse=false callback: 185
20:45:46.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
20:45:46.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:46.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:45:46.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:45:46.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:46.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:48 CEST 2017 - 1994ms
20:45:46.278 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
20:45:46.280 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
20:45:46.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:46.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:46.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:46.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1282: [WAIT_RESPONSE] requiresResponse=false callback: 185
20:45:46.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
20:45:46.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1282: [WAIT_RESPONSE] requiresResponse=false callback: 185
20:45:46.290 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:46.292 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack.
20:45:46.292 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance ST: WAIT_RESPONSE
20:45:46.293 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance WT: ApplicationCommandHandler {}
20:45:46.294 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
20:45:46.295 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance TO: WAIT_REQUEST
20:45:46.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1282: Advanced to WAIT_REQUEST
20:45:46.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 1282: Transaction not completed
20:45:46.298 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:46.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:45:46.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:45:46.301 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:45:46.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Jul 24 20:45:51 CEST 2017 - 4995ms
20:45:50.399 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 B9 01 01 9C CE
20:45:50.401 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
20:45:50.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=185, payload=B9 01 01 9C
20:45:50.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=185, payload=B9 01 01 9C
20:45:50.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=185, payload=B9 01 01 9C
20:45:50.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1282: [WAIT_REQUEST] requiresResponse=false callback: 185
20:45:50.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
20:45:50.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1282: [WAIT_REQUEST] requiresResponse=false callback: 185
20:45:50.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 1282: (Callback 185)
20:45:50.406 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
20:45:50.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 1282: callback 185
20:45:50.407 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=185, payload=B9 01 01 9C
20:45:50.408 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 185, Status = Transmission complete, no ACK received(1)
20:45:50.408 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: Transaction CANCELLED
20:45:50.409 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance ST: CANCELLED
20:45:50.409 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance WT: ApplicationCommandHandler {}
20:45:50.410 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=185, payload=B9 01 01 9C
20:45:50.410 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1282: TransactionAdvance TO: CANCELLED
20:45:50.410 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
20:45:50.411 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
20:45:50.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 1282: Transaction completed
20:45:50.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:1282 CANCELLED
20:45:50.413 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
20:45:50.423 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
20:45:50.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:45:50.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
20:45:50.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
20:45:50.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
20:45:50.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer

Is it possible that signal routing is not happening and instead the controller tries to reach each device directly? Is there a way to check that? Does the HABmin Network Viewer actually work and depict a representation of the mesh?

I would think that’s unlikely, but there’s no way to know. The controller is solely responsible for the routing - it knows the routing tables, it knows the network topology, and it decides the routes. There’s no way to turn this off (as far as I’m aware anyway).

From the binding perspective, there doesn’t appear to be anything wrong, but the device doesn’t respond which means it’s out of range of the controller, or isn’t working or something like that.

Ok, then the issue is likely related to poor signal transmission. It seems that despite all devices shown as online and connected in a mesh (as shown by the Network Viewer) commands are not getting through. Sometimes it switches the lights on, sometimes not. I guess I will have to play trial and error with the location of the various nodes to optimize the mesh network.

Sorry to resurrect this old thread, but I’m seeing a very similar debug with zwave transactions getting into CANCELLED state (debug log below). I think, like this original post, that my door lock is just too far away - some communication works but the majority fail. I’ll look into getting a repeater between the hub and the door to resolve the issue, but it brings to mind the following question:

If this is correct, that the command is failing and is known to be failing due to the CANCELLED status - shouldn’t this be logged at INFO or above level? I’d like to be able to know that my commands are failing - especially for something like a door lock.

Thanks!
Tim

==> /var/log/openhab2/events.log <==
2018-01-07 07:31:51.905 [ome.event.ItemCommandEvent] - Item 'BackDoor_lock_door' received command ON

==> /var/log/openhab2/openhab.log <==
2018-01-07 07:31:51.909 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:160ce8d44df:node6:lock_door --> ON

==> /var/log/openhab2/events.log <==
2018-01-07 07:31:51.919 [vent.ItemStateChangedEvent] - BackDoor_lock_door changed from OFF to ON

==> /var/log/openhab2/openhab.log <==
2018-01-07 07:31:51.912 [DEBUG] [mmandclass.ZWaveDoorLockCommandClass] - NODE 6: Creating new message for application command DOORLOCK_SET, value 255
2018-01-07 07:31:51.925 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
2018-01-07 07:31:51.929 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Encapsulating message, endpoint 0
2018-01-07 07:31:51.932 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: SECURITY required on COMMAND_CLASS_DOOR_LOCK
2018-01-07 07:31:51.935 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: Command Class COMMAND_CLASS_DOOR_LOCK is required to be secured
2018-01-07 07:31:51.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Adding to device queue
2018-01-07 07:31:51.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Added to queue - size 1
2018-01-07 07:31:51.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-01-07 07:31:51.946 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == true, awake == false
2018-01-07 07:31:51.949 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2018-01-07 07:31:51.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: Transaction requires security
2018-01-07 07:31:51.955 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 6: isNonceAvailable = null
2018-01-07 07:31:51.958 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_GET version 1
2018-01-07 07:31:51.961 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SECURITY
2018-01-07 07:31:51.966 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 06 02 98 40 25 BE A2 
2018-01-07 07:31:51.970 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 6: Sending REQUEST Message = 01 09 00 13 06 02 98 40 25 BE A2 
2018-01-07 07:31:51.973 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-01-07 07:31:51.976 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-01-07 07:31:51.976 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: Transaction Start type SendData 
2018-01-07 07:31:51.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1044: [WAIT_RESPONSE] requiresResponse=true callback: 190
2018-01-07 07:31:51.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2018-01-07 07:31:51.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_SECURITY
2018-01-07 07:31:51.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2018-01-07 07:31:51.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 128
2018-01-07 07:31:51.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2018-01-07 07:31:51.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-01-07 07:31:51.991 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-01-07 07:31:51.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-01-07 07:31:51.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2018-01-07 07:31:51.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-01-07 07:31:51.997 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2018-01-07 07:31:51.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jan 07 07:31:53 PST 2018 - 2000ms
2018-01-07 07:31:51.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2018-01-07 07:31:52.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1044: [WAIT_RESPONSE] requiresResponse=true callback: 190
2018-01-07 07:31:52.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-01-07 07:31:52.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2018-01-07 07:31:52.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2018-01-07 07:31:52.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jan 07 07:31:53 PST 2018 - 1990ms
2018-01-07 07:31:52.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2018-01-07 07:31:52.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-01-07 07:31:52.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jan 07 07:31:53 PST 2018 - 1974ms
2018-01-07 07:31:52.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2018-01-07 07:31:52.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1044: [WAIT_RESPONSE] requiresResponse=true callback: 190
2018-01-07 07:31:52.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-01-07 07:31:52.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1044: [WAIT_RESPONSE] requiresResponse=true callback: 190
2018-01-07 07:31:52.030 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2018-01-07 07:31:52.032 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: sentData successfully placed on stack.
2018-01-07 07:31:52.034 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance ST: WAIT_RESPONSE
2018-01-07 07:31:52.035 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance WT: ApplicationCommandHandler {}
2018-01-07 07:31:52.037 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2018-01-07 07:31:52.039 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance TO: WAIT_REQUEST
2018-01-07 07:31:52.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1044: Advanced to WAIT_REQUEST
2018-01-07 07:31:52.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 1044: Transaction not completed
2018-01-07 07:31:52.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-01-07 07:31:52.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2018-01-07 07:31:52.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2018-01-07 07:31:52.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-01-07 07:31:52.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Sun Jan 07 07:31:57 PST 2018 - 4993ms
2018-01-07 07:31:55.497 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 BE 01 01 60 35 
2018-01-07 07:31:55.501 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2018-01-07 07:31:55.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=190, payload=BE 01 01 60 
2018-01-07 07:31:55.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=190, payload=BE 01 01 60 
2018-01-07 07:31:55.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=190, payload=BE 01 01 60 
2018-01-07 07:31:55.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1044: [WAIT_REQUEST] requiresResponse=true callback: 190
2018-01-07 07:31:55.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-01-07 07:31:55.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1044: [WAIT_REQUEST] requiresResponse=true callback: 190
2018-01-07 07:31:55.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 1044: (Callback 190)
2018-01-07 07:31:55.521 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-01-07 07:31:55.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 1044: callback 190
2018-01-07 07:31:55.526 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=190, payload=BE 01 01 60 
2018-01-07 07:31:55.529 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 6: SendData Request. CallBack ID = 190, Status = Transmission complete, no ACK received(1)
2018-01-07 07:31:55.531 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: Transaction CANCELLED
2018-01-07 07:31:55.533 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance ST: CANCELLED
2018-01-07 07:31:55.534 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance WT: ApplicationCommandHandler {}
2018-01-07 07:31:55.537 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=190, payload=BE 01 01 60 
2018-01-07 07:31:55.539 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1044: TransactionAdvance TO: CANCELLED
2018-01-07 07:31:55.541 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-01-07 07:31:55.544 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-01-07 07:31:55.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: TID 1044: Transaction completed
2018-01-07 07:31:55.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: notifyTransactionResponse TID:1044 CANCELLED
2018-01-07 07:31:55.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 6: processing secure transaction -- TID:1043
2018-01-07 07:31:55.553 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-01-07 07:31:55.555 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-01-07 07:31:55.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-01-07 07:31:55.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-01-07 07:31:55.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2018-01-07 07:31:55.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2018-01-07 07:31:55.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer

This is always a tough call - different people want to see things at different levels. Some people would complain about too much logging I suspect :wink:

However, the bottom line is that would not be consistent with the coding guidelines.

Only few important things should be logged in info level, e.g. a newly started component or a user file that has been loaded.

Well I can’t say I agree with that, but it’s a reasonable point of view whatever I think :wink:

The next section seems more interesting then:

For bindings, you should NOT log errors, if e.g. connections are dropped - this is considered to be an external problem and from a system perspective to be a normal and expected situation. The correct way to inform users about such events is to update the Thing status accordingly. Note that all events (including Thing status events) are anyhow already logged.

Is there some way to see these communication issues in a Thing status then? I can’t see anything.