Zwave delays

[cgeo (Christos)]

Hello,

I have a simple rule that when a door is closed, lights are turned on. I notice that I often have a considerable delay in switching on the lights once the door have been opened. In the events.log the messages are taking place at the same time, so no delay there between opening the door and switching on the lights command. I think the problem comes from zwave.

You can see it here from Chris Jackson’s log viewerb

Node 6 is the door sensor and node 5 is the dimmer

Here is the network overview from habmin

The dimmer is relatively close to the controller but I am not sure why it is not directly connected and the door sensor which is in the same location is directly connected. Is it because the dimmer is in the wall ? (fibaro dimmer module)

Is this the problem ?

[rossko57]

@cgeo

In the events.log the messages are taking place at the same time

Sure, but that may be because the door event is delayed arriving on openHAB bus (and into log).
Can you give us an idea of the magnitude of the delay, seconds? minutes?

If the delay were occurring between openHAB command → device, you would be able to reproduce it from UI switch. A command is a command, whether by rule or user clicking.

[cgeo (Christos)]

No the time in the logs is correct. The delay is in 5-15 seconds more or less but it is not always happening.
Openhab runs on a raspi 3 and there is no load that could contribute to that. Yes this happens also when using a switch so it is not rule related. Is it not the delay visible in the logs ?I am not sure how to interpret them

[chris (Chris Jackson)]

@cgeo

The delay is in 5-15 seconds more or less but it is not always happening.

The delay is caused by timeouts - these are 5 seconds, and it can be repeated 3 times.

@cgeo

Openhab runs on a raspi 3 and there is no load that could contribute to that.

It’s not linked to the host - it’s simply down to the ZWave network. Normally this is related to poor RF links between devices.

[cgeo (Christos)]

Thanks @chris. I have another trace where there is almost 30 secs delay of switching on the lights after the door has closed
Is it 15 secs from the door sensor to the controller and then another 15 secs from the controller to the dimmer ?
The dimmer and the door sensor are really not that far from the controller (7m) but on different rooms so there is wall in between
The dimmer is not even battery powered so I am a bit surprised this is due to poor network. Is there any way we can prove it in the logs so next time I know what to look for ?

I can see for example that the controller receives the door closed message at 19:41:17 and the first transmit data towards the dimmer is 5 seconds afterwards already at 19:41:22. Why is it not instantaneous ?

This is how I interpret the logs

Door closed

2019-05-29 19:41:17.353 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Updating channel state zwave:device:fb544589:node6:sensor_door to CLOSED [OpenClosedType]

Request received to switch on the lights through the dimmer

2019-05-29 19:41:17.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:fb544589:node5:switch_dimmer1 --> 70 [PercentType]

It created a TID (transaction ID??) and adds it to the queue

2019-05-29 19:41:17.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added 156156 to queue - size 11

For some reason it starts pooling the dimmer node (what does this mean?)
This adds a delay of two seconds already

2019-05-29 19:41:17.500 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling intialised at 86400 seconds - start in 1500 milliseconds.

Messages is sent to Node 5 and waiting

2019-05-29 19:41:22.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 156156: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 243

There is a timeout (controller did not get a reply ?)

2019-05-29 19:41:27.575 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 5: TID 156156: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-05-29 19:41:27.577 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!

Finally this transaction is cancelled

2019-05-29 19:41:39.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:156156 CANCELLED

and out of the blue I see the dimmer getting the request to switch on the lights

2019-05-29 19:41:46.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2019-05-29 19:41:46.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2019-05-29 19:41:46.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-05-29 19:41:46.509 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2019-05-29 19:41:46.510 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2019-05-29 19:41:46.511 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 5: Switch Multi Level report, value = 70

I attach the log here
zwave.txt (101.1 KB)

[chris (Chris Jackson)]

It looks like the dongle is busy doing something else, so the frame is queued until this completes. Possibly this is part of the daily heal and this is why this is normally run in the middle of the night?

[cgeo (Christos)]

No the healing started for both devices late at night as you said. I am not sure if there is a hog on the usb stick or just wireless issues
I have plugged another zwave node in between the dimmer / door sensor and the controller to see if this makes any difference

Thanks

[chris (Chris Jackson)]

If this is a battery device, then it could still be the heal as it will take time due to sleeping. In any case, heal or not, that is the cause of the delay.

[peterloron]

Is there a way (debug log, cli tool, etc) to monitor the signal strength and connection quality (packet loss, etc) of the zwave or zigbee network?

I also see occasional delays between some triggers and responses. I think I have good coverage of wired devices between the battery operated trigger and the openhab machine.

[cgeo (Christos)]

@chris

In any case, heal or not, that is the cause of the delay.

Busy dongle ?

[chris (Chris Jackson)]

Some of the maintenance commands take quite a long time and the ZWave dongle doesn’t allow multiple transactions.

[rafdalb (Raffaele)]

Should we see these maintenance commands in the logs? I’ve the same problem and I don’t think it’s radio related. In my case the Z-wave network seems to be pretty fast sending messages from sensors to dongle, but very slow (with delays up to 30 seconds) from the dongle to the device.

This is the log output related to the specific node.

The moment I send the command to openhab is :28, and the light switches on at :51.

2019-09-22 10:58:28.151 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 00 25 35 C0 
2019-09-22 10:58:28.205 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: sentData successfully placed on stack.
2019-09-22 10:58:28.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 110: Transaction not completed
2019-09-22 10:58:28.240 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 53, Status = Transmission complete and ACK received(0)
2019-09-22 10:58:28.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
2019-09-22 10:58:28.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Response processed after 93ms
2019-09-22 10:58:28.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 110: Transaction completed
2019-09-22 10:58:28.257 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:110 DONE
2019-09-22 10:58:28.259 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-22 10:58:28.268 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 63 25 36 A0 
2019-09-22 10:58:28.296 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: sentData successfully placed on stack.
2019-09-22 10:58:28.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 114: Transaction not completed
2019-09-22 10:58:28.322 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 54, Status = Transmission complete and ACK received(0)
2019-09-22 10:58:28.324 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
2019-09-22 10:58:28.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Response processed after 53ms
2019-09-22 10:58:28.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 114: Transaction completed
2019-09-22 10:58:28.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:114 DONE
2019-09-22 10:58:28.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-22 10:58:51.373 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 09 00 13 12 02 26 02 25 3D C9 
2019-09-22 10:58:51.418 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: sentData successfully placed on stack.
2019-09-22 10:58:51.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 115: Transaction not completed
2019-09-22 10:58:51.449 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 61, Status = Transmission complete and ACK received(0)
2019-09-22 10:58:51.451 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
2019-09-22 10:58:51.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 115: Transaction not completed
2019-09-22 10:58:51.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Application Command Request (ALIVE:DONE)
2019-09-22 10:58:51.461 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
2019-09-22 10:58:51.463 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-09-22 10:58:51.464 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
2019-09-22 10:58:51.466 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 18: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_REPORT
2019-09-22 10:58:51.467 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Switch Multi Level report, value = 99
2019-09-22 10:58:51.469 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-09-22 10:58:51.471 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 99
2019-09-22 10:58:51.473 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Updating channel state zwave:device:aeotec:node18:switch_dimmer to 100 [PercentType]
2019-09-22 10:58:51.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Commands processed 1.
2019-09-22 10:58:51.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f46a84.
2019-09-22 10:58:51.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f46a84.
2019-09-22 10:58:51.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:115 DONE
2019-09-22 10:58:51.483 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

[chris (Chris Jackson)]

Please provide the full log - do not filter on one node. Also, if you paste logs into your message, please use code fences so that it’s readable (I’ve edited your message to fix this).

[rafdalb (Raffaele)]

These are the full logs approx between Node 18 switch on and light which effectively switched on.

2019-09-22 11:52:47.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:47.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:47.734 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 2C 00 00 08 CF 
2019-09-22 11:52:47.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=44, payload=2C 00 00 08 
2019-09-22 11:52:47.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=44, payload=2C 00 00 08 
2019-09-22 11:52:47.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 92: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 44
2019-09-22 11:52:47.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 11:52:47.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 92: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 44
2019-09-22 11:52:47.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 92: (Callback 44)
2019-09-22 11:52:47.746 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-22 11:52:47.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 92: callback 44
2019-09-22 11:52:47.749 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=44, payload=2C 00 00 08 
2019-09-22 11:52:47.751 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 44, Status = Transmission complete and ACK received(0)
2019-09-22 11:52:47.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 92: Advanced to WAIT_DATA
2019-09-22 11:52:47.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: TID 92: Transaction not completed
2019-09-22 11:52:47.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:47.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:48.319 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 07 05 31 05 05 01 33 F1 
2019-09-22 11:52:48.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=7, callback=0, payload=00 07 05 31 05 05 01 33 
2019-09-22 11:52:48.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=7, callback=0, payload=00 07 05 31 05 05 01 33 
2019-09-22 11:52:48.326 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-22 11:52:48.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Application Command Request (ALIVE:DYNAMIC_VALUES)
2019-09-22 11:52:48.329 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2019-09-22 11:52:48.330 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY not supported
2019-09-22 11:52:48.332 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 7: Received COMMAND_CLASS_SENSOR_MULTILEVEL V5 SENSOR_MULTILEVEL_REPORT
2019-09-22 11:52:48.333 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 7: Sensor Type = RelativeHumidity(5), Scale = 0
2019-09-22 11:52:48.335 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 7: Sensor Value = 51
2019-09-22 11:52:48.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-09-22 11:52:48.338 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 51
2019-09-22 11:52:48.340 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 7: Sensor conversion not performed for RELATIVE_HUMIDITY.
2019-09-22 11:52:48.341 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating channel state zwave:device:aeotec:node7:sensor_relhumidity to 51 [DecimalType]
2019-09-22 11:52:48.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Commands processed 1.
2019-09-22 11:52:48.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1fbbd90.
2019-09-22 11:52:48.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1fbbd90.
2019-09-22 11:52:48.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: notifyTransactionResponse TID:92 DONE
2019-09-22 11:52:48.353 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-09-22 11:52:48.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 92: Transaction event listener: DONE: DONE -> 
2019-09-22 11:52:48.355 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@15a39b1
2019-09-22 11:52:48.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-09-22 11:52:48.356 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node Init transaction completed with response COMPLETE
2019-09-22 11:52:48.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-22 11:52:48.358 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_WAKE_UP
2019-09-22 11:52:48.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:48.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 11:52:48.359 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_MANUFACTURER_SPECIFIC
2019-09-22 11:52:48.362 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_CONFIGURATION
2019-09-22 11:52:48.363 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 0D 96 
2019-09-22 11:52:48.365 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BASIC
2019-09-22 11:52:48.366 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 0D 96 
2019-09-22 11:52:48.367 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_ASSOCIATION
2019-09-22 11:52:48.368 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 11:52:48.371 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 11:52:48.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 93: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:48.373 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking COMMAND_CLASS_BATTERY
2019-09-22 11:52:48.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 11:52:48.377 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Found 1 instances of COMMAND_CLASS_BATTERY for endpoint 0
2019-09-22 11:52:48.380 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY not supported
2019-09-22 11:52:48.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 11:52:48.383 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Command Class COMMAND_CLASS_BATTERY is NOT required to be secured
2019-09-22 11:52:48.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 93: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:48.384 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
2019-09-22 11:52:48.386 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: ZWaveCommandClassTransactionPayload - send to node
2019-09-22 11:52:48.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 11:52:48.390 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: SECURITY not supported
2019-09-22 11:52:48.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:48.394 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: Command Class COMMAND_CLASS_BATTERY is NOT required to be secured
2019-09-22 11:52:48.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:48.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@400f28
2019-09-22 11:52:48.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:48.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Adding to device queue
2019-09-22 11:52:48.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:48.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Added 94 to queue - size 9
2019-09-22 11:52:48.406 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 93: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:48.408 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:48.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 11:52:48.415 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 93: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:48.419 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:48.422 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2019-09-22 11:52:48.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 93: Advanced to WAIT_DATA
2019-09-22 11:52:48.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 93: Transaction not completed
2019-09-22 11:52:48.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:48.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
==> /var/log/openhab2/events.log <==
2019-09-22 11:52:49.612 [ome.event.ItemCommandEvent] - Item 'Bathroom_Light' received command 100
2019-09-22 11:52:49.623 [nt.ItemStatePredictedEvent] - Bathroom_Light predicted to become 100
==> /var/log/openhab2/openhab.log <==
2019-09-22 11:52:49.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Command received zwave:device:aeotec:node18:switch_dimmer --> 100 [PercentType]
2019-09-22 11:52:49.633 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_SET
2019-09-22 11:52:49.640 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
2019-09-22 11:52:49.647 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
==> /var/log/openhab2/events.log <==
2019-09-22 11:52:49.647 [vent.ItemStateChangedEvent] - Bathroom_Light changed from 0 to 100
==> /var/log/openhab2/openhab.log <==
2019-09-22 11:52:49.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue
2019-09-22 11:52:49.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Added 95 to queue - size 10
2019-09-22 11:52:49.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:49.664 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling intialised at 1800 seconds - start in 1500 milliseconds.
2019-09-22 11:52:51.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling...
2019-09-22 11:52:51.168 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:aeotec:node18:switch_dimmer
2019-09-22 11:52:51.172 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 18: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-09-22 11:52:51.174 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_GET
2019-09-22 11:52:51.178 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY not supported
2019-09-22 11:52:51.180 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-09-22 11:52:51.184 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling skipped for zwave:device:aeotec:node18:switch_dimmer on COMMAND_CLASS_BASIC
2019-09-22 11:52:51.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue
2019-09-22 11:52:51.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Added 96 to queue - size 11
2019-09-22 11:52:51.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:57.954 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 
2019-09-22 11:52:57.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2019-09-22 11:52:57.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2019-09-22 11:52:57.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 93: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:57.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 11:52:57.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 93: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2019-09-22 11:52:57.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 93: (Callback 0)
2019-09-22 11:52:57.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 93: callback 0
2019-09-22 11:52:57.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2019-09-22 11:52:57.979 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 13: Application update request. Node Info Request Failed.
2019-09-22 11:52:57.981 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 93: Transaction CANCELLED
2019-09-22 11:52:57.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: CANCEL while sending message. Requeueing - 2 attempts left!
2019-09-22 11:52:57.985 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 93: Transaction RESET with 2 retries remaining.
2019-09-22 11:52:57.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Adding to device queue
2019-09-22 11:52:57.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: Added 93 to queue - size 12
2019-09-22 11:52:57.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 11:52:58.000 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 12 03 26 01 63 25 2D BB 
2019-09-22 11:52:58.003 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 63 25 2D BB 
2019-09-22 11:52:58.006 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 11:52:58.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 95: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.008 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 11:52:58.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 13: TID 93: Transaction not completed
2019-09-22 11:52:58.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 11:52:58.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 11:52:58.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 11:52:58.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 11:52:58.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-22 11:52:58.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 95: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 11:52:58.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:58.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:58.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 95: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 11:52:58.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 95: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.033 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 2D 00 00 02 C4 
2019-09-22 11:52:58.034 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 11:52:58.036 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: sentData successfully placed on stack.
2019-09-22 11:52:58.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=45, payload=2D 00 00 02 
2019-09-22 11:52:58.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 95: Advanced to WAIT_REQUEST
2019-09-22 11:52:58.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 95: Transaction not completed
2019-09-22 11:52:58.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=45, payload=2D 00 00 02 
2019-09-22 11:52:58.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 95: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 11:52:58.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 95: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 45
2019-09-22 11:52:58.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 95: (Callback 45)
2019-09-22 11:52:58.055 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-09-22 11:52:58.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 95: callback 45
2019-09-22 11:52:58.060 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=45, payload=2D 00 00 02 
2019-09-22 11:52:58.062 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 45, Status = Transmission complete and ACK received(0)
2019-09-22 11:52:58.065 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: resetResendCount initComplete=true isDead=false
2019-09-22 11:52:58.066 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 95: Transaction COMPLETED
2019-09-22 11:52:58.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Response processed after 60ms
2019-09-22 11:52:58.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: TID 95: Transaction completed
2019-09-22 11:52:58.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: notifyTransactionResponse TID:95 DONE
2019-09-22 11:52:58.073 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

[chris (Chris Jackson)]

For your information -:

How to use code fences

We all have to type this content over and over and over. Here is a posting we can all point to when the topic comes up. Why use code fences? Because rules, sitemap, logs, and configs are all but unreadable when code fences are not used. When to use code fences? Whenever one is posting any sort of code, config, log, and any text where line wrapping, indentation, and using an equal spaced font makes the text more legible. How to use code fences? Use 3 backticks (```)... Or use <code>... …

[chris (Chris Jackson)]

Your problem is caused by node 13 not responding to some commands, and this is slowing down other communications in the network.

[rafdalb (Raffaele)]

code between <> didn’t work in my case, I changed it with the “’’’” and worked now.

Just FYI.

Sorry for the off topic, you can remove this message if you want as it’s not useful to solve the problem in my view.

This was just to let you know.

[rafdalb (Raffaele)]

Thanks,

Node 13 is dead, the problem is that I don’t know how to remove it from the network. I don’t have windows machines at home (only MacOS and Linux) so can’t use Zensys tools as suggested on some forums.

Is there an alternative way to remove nodes from Zwave Controllers other than Zensys tools?

Thanks a lot,
Raf.

[sihui]

@rafdalb

Is there an alternative way to remove nodes from Zwave Controllers other than Zensys tools?

In HABmin, mark the node as failed, then remove device from controller. To see those options you need to switch to advanced settings of that node.

[rafdalb (Raffaele)]

Already tried by I get this error: