Zwave delays

cgeo · May 29, 2019, 11:37pm

Busy dongle ?

chris · May 30, 2019, 6:28am

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

rafdalb · September 22, 2019, 9:19am

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 · September 22, 2019, 9:21am

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 · September 22, 2019, 1:52pm

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 · September 22, 2019, 1:57pm

For your information -:

chris · September 22, 2019, 1:59pm

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

rafdalb · September 22, 2019, 1:59pm

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 · September 22, 2019, 3:10pm

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 · September 22, 2019, 3:14pm

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.

grafik

rafdalb · September 22, 2019, 3:26pm

Already tried by I get this error:

chris · September 22, 2019, 3:27pm

When do you get this error?

rafdalb · September 22, 2019, 3:28pm

When I try to mark the device as failed on HABmin…

And this is the log I see when I try to run the command:

2019-09-22 17:29:31.384 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration update received
2019-09-22 17:29:31.392 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Configuration update set action_failed to true (Boolean)
2019-09-22 17:29:31.396 [DEBUG] [message.RemoveFailedNodeMessageClass] - NODE 13: Marking node as having failed.
2019-09-22 17:29:31.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 818 to queue - size 1
2019-09-22 17:29:31.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:31.408 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 0D 01 7C E8 
2019-09-22 17:29:31.412 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 0D 01 7C E8 
2019-09-22 17:29:31.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 17:29:31.419 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 17:29:31.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:31.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:31.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 17:29:31.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:31.441 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 08 93 
2019-09-22 17:29:31.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:31.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2019-09-22 17:29:31.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
2019-09-22 17:29:31.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
2019-09-22 17:29:31.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:31.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 818: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 124
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.471 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:aeotec:node13' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=08 
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.474 [vent.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.484 [DEBUG] [message.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.
2019-09-22 17:29:31.486 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 13: Remove failed node failed as node not found
2019-09-22 17:29:31.489 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 818: Transaction COMPLETED
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:31.494 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@55d0ca
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:31.497 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Got an event from Z-Wave network: ZWaveNetworkEvent
2019-09-22 17:29:31.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 80ms
2019-09-22 17:29:31.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 818: Transaction completed
2019-09-22 17:29:31.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:818 DONE
2019-09-22 17:29:31.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:31.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:40.810 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 10 02 84 07 62 
2019-09-22 17:29:40.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 02 84 07 
2019-09-22 17:29:40.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=16, callback=0, payload=00 10 02 84 07 
2019-09-22 17:29:40.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-09-22 17:29:40.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Application Command Request (ALIVE:DONE)
2019-09-22 17:29:40.822 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
2019-09-22 17:29:40.823 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Is awake with 0 messages in the queue
2019-09-22 17:29:40.825 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Start sleep timer at 1000ms
2019-09-22 17:29:40.827 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-09-22 17:29:40.848 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is AWAKE
2019-09-22 17:29:40.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Commands processed 1.
2019-09-22 17:29:40.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ea09de.
2019-09-22 17:29:40.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
==> /var/log/openhab2/events.log <==
2019-09-22 17:29:40.853 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:aeotec:node16' has been updated.
==> /var/log/openhab2/openhab.log <==
2019-09-22 17:29:40.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-09-22 17:29:40.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:40.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:41.327 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-22 17:29:41.827 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: WakeupTimerTask 0 Messages waiting, state DONE
2019-09-22 17:29:41.828 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: No more messages, go back to sleep
2019-09-22 17:29:41.830 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 16: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2019-09-22 17:29:41.831 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2019-09-22 17:29:41.833 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2019-09-22 17:29:41.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@11fdc7
2019-09-22 17:29:41.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Bump transaction 819 priority from Immediate to Immediate
2019-09-22 17:29:41.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2019-09-22 17:29:41.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 819 to queue - size 5
2019-09-22 17:29:41.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-22 17:29:41.843 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 10 02 84 08 25 7D 23 
2019-09-22 17:29:41.845 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 09 00 13 10 02 84 08 25 7D 23 
2019-09-22 17:29:41.847 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-22 17:29:41.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.850 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-09-22 17:29:41.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:41.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-09-22 17:29:41.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.856 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-09-22 17:29:41.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-09-22 17:29:41.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:41.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.860 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:41.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:41.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 819: [WAIT_RESPONSE] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:41.874 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-09-22 17:29:41.876 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.
2019-09-22 17:29:41.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 819: Advanced to WAIT_REQUEST
2019-09-22 17:29:41.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 819: Transaction not completed
2019-09-22 17:29:41.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-22 17:29:41.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-22 17:29:46.185 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 7D 01 01 B1 27 
2019-09-22 17:29:46.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 01 B1 
2019-09-22 17:29:46.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=125, payload=7D 01 01 B1 
2019-09-22 17:29:46.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 819: [WAIT_REQUEST] priority=Immediate, requiresResponse=true, callback: 125
2019-09-22 17:29:46.198 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-09-22 17:29:46.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 819: [WA

chris · September 22, 2019, 3:38pm

I believe that this means that the device is not considered failed by the controller, but Silabs have removed the documentation from their website now as the close down access to the new API . I will need to try and find the docs on my old computer.

rafdalb · September 22, 2019, 4:53pm

That means Zensys tools would not be able to remove the device anyway. I assume, I’m wondering how to fix the issue then;

should I reset everything (although I would like to avoid it, just to understand what’s the alternative)?

Thanks,
Raf.

chris · September 22, 2019, 5:36pm

Some people have been able to use the Zensys tool to remove devices, and some can’t. We spent some time a year or so back confirming that the binding is sending exactly the same commands as the Zensys tool, so I think it’s likely that you will have he same result.

OMR · September 23, 2019, 11:16pm

It’s been a while, but I remember I sometimes had to try several times in order to successfully remove nodes in Zensys. It always worked in the end though.

OMR · September 25, 2019, 5:51pm

My Z-Wave network acted up again today.
Was able to ‘sneak’ past a sensor without any lights turning on. Hitting a Z-Wave wall switch. Took 10s for the Zigbee lights to go off, Z-Wave lights in group stayed on.

Using my z-wave sniffer I immediately noticed 2 nodes spewing out messages completely swamping the network. Power-cycled them; sniffer logs calmed down and wall switch worked fine again.

Nodes that acted up this time was (differs) : ZW096 Smart Switch 6 & HEATIT Z-RELAY Multipurpose relay

chris · September 26, 2019, 7:21am

Was this also visible in the openhab log? This is not as uncommon an event as you’d hope and I’m wondering if it’s something I could add some sort of indicator for in the binding. If you have the log showing this, please can you provide it.

OMR · September 26, 2019, 7:23pm

Sorry no. Debug logging was off and I was a bit in a hurry to rectify.
Will try enabling debug logs when it happens again.
This time all messages was addressed correctly to the controller.
Last time they were addressed to a non excisting node.