Cancelled Frames after adding new Z-wave devices

[brianmichalk (Brian Keith Michalk)]

Two weeks ago I added ten new Z-wave devices. The network view showed a lot of red arrows, and I had nodes dropping offline. The log file shows a lot of cancelled frames, along with the “TODO: Implement Application Update Request Handling of New ID Assigned (64).” message.

I’ve tried manually healing the network, but no luck. I figured it would sort itself out over time.

What’s the best way to go about troubleshooting this? I don’t want to do a hard reset on the stick, because then I’d have to add all of the nodes back in.
Before adding the nodes, the network was stable and reliable. It’s strange, but I think adding the new devices inserted a rogue node on the network. It’s like one of them took over routing, because previously installed nodes stopped working properly.

[Andrew_Rowe]

First please tell us your platform and operating system as well as the version of OpenHAB you are using and the version of the zwave binding
What types of devices are the new ones? Are they battery or mains powered? Did all the new devices get fully discovered?
Keep an eye on the logs, set the zwave logs to debug (look in the documentation for the binding on how to set the logs to debug)
Does the system function? Describe the results further
Only mains powered devices can act as repeaters. How is your range? One bad node can flood the system

[brianmichalk (Brian Keith Michalk)]

Openhabian, 2.5.0.M3
Z-wave binding is 2.5.0.M3
The new devices are all Mains powered, Honeywell, 39358 fan control, 39351 light dimmer.
The system works, but not reliably.
All of the new switches are mounted within two feet of each other. Across the dance floor, about 70 feet away is another couple of mains powered nodes, and 30 feet behind that wall is the controller. Previous to these new nodes, I had mains powered thermostats that are physically farther separated, and the network was stable. These new nodes are closer to the center of the network, so they should have been able to talk to a close neighbor that was already stable on the network. Adding these new nodes caused some of the previously stable nodes to drop off the network. This is strange because I installed the new ones without including them to the controller, and some of the stable nodes dropped offline.

[Bruce_Osborne]

That TODO message indicates to me there is some binding development needed. @chris would know for sure. If so, opening an issue on GitHub is the proper step.
If those nodes are affecting network stability perhaps they need to be excluded until the binding is updated.

[chris (Chris Jackson)]

I’d need to see a debug log to understand exactly what this is and if it is something that matters or if it is even caused by something like corrupted frames.

What controller are you using?

[Ryan_Illman]

I’m having a nearly identical problem, I added 3 new devices a couple days ago, and ever since I’m randomly losing nodes and my log is full of the TODO message.

Openhab 2.5.0M2 via openhabian. Controller is labeled “Nortek Security and Control HUSBZB-1” and reports in lsusb as vendor 0x10c4 “Cygnal Integrated Products, inc” product 0x8a2a (no name).

Here’s a snippet of debug log that contains the TODO message.
zwave_debug_log.txt (16.7 KB)

[Bruce_Osborne]

@Ryan_Illman

Controller is labeled “Nortek Security and Control HUBBZB-1”

I have used that controller successfully in Milestone 2 and for quite a while on Milestone 3 with no issues.

EDIT: I assume you made a typo. I have the HUSBZB-1 not HUBBZB-1

[Ryan_Illman]

Correct, HUSBZB-1. I haven’t had any issues with it until now.

[Ryan_Illman]

Here’s a log snippet where a device went offline. If I see it come back online I’ll post that snippet as well.
zwave_dead_device.txt (16.4 KB)

[chris (Chris Jackson)]

Do you have multiple controllers in the network? I’m not sure why a node should change IDs otherwise…

[Ryan_Illman]

Just the one.

[Ryan_Illman]

Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=36, callback=64, payload=40 24 10 04 11 07 5E 86 72 5A 85 59 73 80 71 31 70 84 7A 
TODO: Implement Application Update Request Handling of New ID Assigned (64).

does dest=36 indicate that it’s node 36 in this message?

[chris (Chris Jackson)]

Yes.

[brianmichalk (Brian Keith Michalk)]

Here is a portion of my log file from a few days ago during the heal process. I can send more log files if needed.

2019-10-13 03:02:10.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@ed2ffa
2019-10-13 03:02:10.549 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Adding to device queue
2019-10-13 03:02:10.550 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: Added 32665 to queue - size 1
2019-10-13 03:02:10.551 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:02:10.553 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 18 C9 63 
2019-10-13 03:02:10.555 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 18 C9 63 
2019-10-13 03:02:10.558 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-10-13 03:02:10.556 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-10-13 03:02:10.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:02:10.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32665: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 201
2019-10-13 03:02:10.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:02:10.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:02:10.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-10-13 03:02:10.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:02:10.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:02:10.719 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 40 18 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A F9 
2019-10-13 03:02:10.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=64, payload=40 18 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:02:10.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=64, payload=40 18 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:02:10.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:02:10.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-10-13 03:02:10.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-10-13 03:02:10.728 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=24, callback=64, payload=40 18 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:02:10.729 [WARN ] [essage.ApplicationUpdateMessageClass] - TODO: Implement Application Update Request Handling of New ID Assigned (64).
2019-10-13 03:02:10.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:02:10.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:02:15.563 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 24: TID 32665: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-10-13 03:02:15.565 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 32665: Transaction is current transaction, so clearing!!!!!
2019-10-13 03:02:15.566 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32665: Transaction CANCELLED
2019-10-13 03:02:15.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 24: notifyTransactionResponse TID:32665 CANCELLED
2019-10-13 03:02:15.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:02:15.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 32665: Transaction event listener: DONE: CANCELLED -> 
2019-10-13 03:02:15.574 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 24: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@9a69c9
2019-10-13 03:02:20.481 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 C9 22 59 
2019-10-13 03:02:20.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=201, payload=C9 22 
2019-10-13 03:02:20.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=201, payload=C9 22 
2019-10-13 03:02:20.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:02:20.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-10-13 03:02:20.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-10-13 03:02:20.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=201, payload=C9 22 
2019-10-13 03:02:20.496 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NodeNeighborUpdate request without transaction
2019-10-13 03:02:20.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:02:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:03:42.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1439d5d
2019-10-13 03:03:42.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
2019-10-13 03:03:42.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Added 32666 to queue - size 1
2019-10-13 03:03:42.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:03:42.441 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 48 15 CA 6D 
2019-10-13 03:03:42.443 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 15 CA 6D 
2019-10-13 03:03:42.445 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-10-13 03:03:42.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32666: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 202
2019-10-13 03:03:42.447 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-10-13 03:03:42.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:03:42.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:03:42.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:03:42.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-10-13 03:03:42.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:03:42.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:03:42.984 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 49 40 15 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A F4 
2019-10-13 03:03:42.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=21, callback=64, payload=40 15 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:03:42.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=21, callback=64, payload=40 15 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:03:42.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:03:42.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-10-13 03:03:42.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-10-13 03:03:42.998 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=21, callback=64, payload=40 15 11 04 11 01 5E 56 86 72 5A 85 59 73 26 27 70 2C 2B 7A 
2019-10-13 03:03:43.000 [WARN ] [essage.ApplicationUpdateMessageClass] - TODO: Implement Application Update Request Handling of New ID Assigned (64).
2019-10-13 03:03:43.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:03:43.002 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:03:47.450 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 21: TID 32666: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-10-13 03:03:47.452 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 32666: Transaction is current transaction, so clearing!!!!!
2019-10-13 03:03:47.452 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 32666: Transaction CANCELLED
2019-10-13 03:03:47.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:32666 CANCELLED
2019-10-13 03:03:47.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:03:47.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 32666: Transaction event listener: DONE: CANCELLED -> 
2019-10-13 03:03:47.457 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1d3c841
2019-10-13 03:03:53.234 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 CA 22 5A 
2019-10-13 03:03:53.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=202, payload=CA 22 
2019-10-13 03:03:53.243 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=202, payload=CA 22 
2019-10-13 03:03:53.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:03:53.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-10-13 03:03:53.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-10-13 03:03:53.252 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=34, callback=202, payload=CA 22 
2019-10-13 03:03:53.254 [DEBUG] [equestNodeNeighborUpdateMessageClass] - NodeNeighborUpdate request without transaction
2019-10-13 03:03:53.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:03:53.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:04:35.234 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling...
2019-10-13 03:04:35.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling zwave:device:e8358de4:node14:switch_dimmer
2019-10-13 03:04:35.239 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 14: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-10-13 03:04:35.241 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 14: Creating new message for command SWITCH_MULTILEVEL_GET
2019-10-13 03:04:35.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: SECURITY not supported
2019-10-13 03:04:35.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-10-13 03:04:35.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Adding to device queue
2019-10-13 03:04:35.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Added 32667 to queue - size 1
2019-10-13 03:04:35.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:04:35.251 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0E 02 26 02 25 CB 23 
2019-10-13 03:04:35.253 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 14: Sending REQUEST Message = 01 09 00 13 0E 02 26 02 25 CB 23 
2019-10-13 03:04:35.255 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-10-13 03:04:35.258 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32667: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.259 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-10-13 03:04:35.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:04:35.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:04:35.266 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-10-13 03:04:35.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32667: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:35.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-10-13 03:04:35.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:35.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32667: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.277 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-10-13 03:04:35.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32667: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:35.284 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 14: sentData successfully placed on stack.
2019-10-13 03:04:35.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 32667: Advanced to WAIT_REQUEST
2019-10-13 03:04:35.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: TID 32667: Transaction not completed
2019-10-13 03:04:35.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:04:35.292 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-10-13 03:04:35.322 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 CB 00 00 07 27 
2019-10-13 03:04:35.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=203, payload=CB 00 00 07 
2019-10-13 03:04:35.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=203, payload=CB 00 00 07 
2019-10-13 03:04:35.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32667: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-10-13 03:04:35.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32667: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 203
2019-10-13 03:04:35.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 32667: (Callback 203)
2019-10-13 03:04:35.341 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-10-13 03:04:35.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 32667: callback 203
2019-10-13 03:04:35.346 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=203, payload=CB 00 00 07 
2019-10-13 03:04:35.349 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 14: SendData Request. CallBack ID = 203, Status = Transmission complete and ACK received(0)
2019-10-13 03:04:35.352 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: resetResendCount initComplete=true isDead=false
2019-10-13 03:04:35.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 32667: Advanced to WAIT_DATA
2019-10-13 03:04:35.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: TID 32667: Transaction not completed
2019-10-13 03:04:35.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:04:35.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-10-13 03:04:35.394 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 0E 03 26 03 42 98 
2019-10-13 03:04:35.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=14, callback=0, payload=00 0E 03 26 03 42 
2019-10-13 03:04:35.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=14, callback=0, payload=00 0E 03 26 03 42 
2019-10-13 03:04:35.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-13 03:04:35.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Application Command Request (ALIVE:DONE)
2019-10-13 03:04:35.403 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: resetResendCount initComplete=true isDead=false
2019-10-13 03:04:35.405 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-10-13 03:04:35.407 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: SECURITY not supported
2019-10-13 03:04:35.408 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT
2019-10-13 03:04:35.410 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 14: Switch Multi Level report, value = 66
2019-10-13 03:04:35.411 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-10-13 03:04:35.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=66
2019-10-13 03:04:35.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating channel state zwave:device:e8358de4:node14:switch_dimmer to 66 [PercentType]
2019-10-13 03:04:35.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Commands processed 1.
2019-10-13 03:04:35.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@12ff28a.
2019-10-13 03:04:35.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@12ff28a.
2019-10-13 03:04:35.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: notifyTransactionResponse TID:32667 DONE
2019-10-13 03:04:35.426 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-10-13 03:04:35.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-10-13 03:04:35.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-10-13 03:04:35.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:04:35.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:04:58.821 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling...
2019-10-13 03:04:58.825 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling zwave:device:e8358de4:node11:switch_dimmer
2019-10-13 03:04:58.829 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 11: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-10-13 03:04:58.830 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 11: Creating new message for command SWITCH_MULTILEVEL_GET
2019-10-13 03:04:58.833 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: SECURITY not supported
2019-10-13 03:04:58.835 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-10-13 03:04:58.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Adding to device queue
2019-10-13 03:04:58.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Added 32668 to queue - size 1
2019-10-13 03:04:58.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-13 03:04:58.844 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0B 02 26 02 25 CC 21 
2019-10-13 03:04:58.847 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 09 00 13 0B 02 26 02 25 CC 21 
2019-10-13 03:04:58.849 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-10-13 03:04:58.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 32668: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 204
2019-10-13 03:04:58.853 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-10-13 03:04:58.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:04:58.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-10-13 03:04:58.861 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-10-13 03:04:58.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32668: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 204
2019-10-13 03:04:58.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-10-13 03:04:58.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:04:58.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-10-13 03:04:58.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:58.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:58.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32668: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 204
2019-10-13 03:04:58.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-10-13 03:04:58.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 32668: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 204
2019-10-13 03:04:58.879 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-10-13 03:04:58.880 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: sentData successfully placed on stack.
2019-10-13 03:04:58.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 32668: Advanced to WAIT_REQUEST
2019-10-13 03:04:58.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: TID 32668: Transaction not completed
2019-10-13 03:04:58.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-10-13 03:04:58.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-10-13 03:04:58.916 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 CC 00 00 06 21 
2019-10-13 03:04:58.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=204, payload=CC 00 00 06 
2019-10-13 03:04:58.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=204, payload=CC 00 00 06 
2019-10-13 03:04:58.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 32668: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 204

[brianmichalk (Brian Keith Michalk)]

I am using an Aeotek Gen5 stick.

[Bruce_Osborne]

If you are running a snapshot build, the snapshot binding was fixed yesterday.

[brianmichalk (Brian Keith Michalk)]

I’ll check that out. Where is the discussion thread on snapshot builds?

[Ryan_Illman]

Is it possible that the new devices corrupted the whole network beyond what a heal can do? At 9:04 I opened the breaker that my three new devices are attached to in an attempt to see if they are causing interference of some sort.

At 9:08 this happened:

2019-10-17 09:08:32.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=65, callback=64, payload=40 41 10 04 10 01 5E 86 72 5A 85 59 73 80 71 31 70 84 7A 
2019-10-17 09:08:32.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4985: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 248
2019-10-17 09:08:32.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-10-17 09:08:32.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4985: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 248
2019-10-17 09:08:32.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 4985: (Callback 248)
2019-10-17 09:08:32.530 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=65, callback=64, payload=40 41 10 04 10 01 5E 86 72 5A 85 59 73 80 71 31 70 84 7A 
2019-10-17 09:08:32.533 [WARN ] [essage.ApplicationUpdateMessageClass] - TODO: Implement Application Update Request Handling of New ID Assigned (64).

node 65 is one of the three new devices and is currently powered off. I’ll try upgrading to a snapshot build and see what happens.

[Bruce_Osborne]

If you want to update just the zwave binding, I know the script works on M3 and prior.

Zigbee and zwave manual install script

A number of people have run into trouble performing manual installs of the Zigbee and Z-Wave bindings. A manual install (dropping the jar into addons) is rarely needed, but some people prefer a manual install over apt-get, or want to use a stable OH release with a recent Zigbee or Z-Wave binding. Here is a script that will hopefully make it easier to install, upgrade, and uninstall these bindings, and prevent some of the common issues. Who would benefit from this script: Anyone wanting to tes…

[brianmichalk (Brian Keith Michalk)]

This is my fear as well. I thought Z-wave devices could not interact with the network until they were included. If true, then the Zwave security is broken. My other thought was that this was a peer-peer communication, and I did have a node that did not have its association group set to “controller”.