Cancelled Frames after adding new Z-wave devices

brianmichalk · October 17, 2019, 3:28pm

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 · October 17, 2019, 3:30pm

I am using an Aeotek Gen5 stick.

Bruce_Osborne · October 17, 2019, 3:50pm

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

brianmichalk · October 17, 2019, 4:02pm

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

Ryan_Illman · October 17, 2019, 4:12pm

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 · October 17, 2019, 4:13pm

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

brianmichalk · October 17, 2019, 4:52pm

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”.

brianmichalk · October 17, 2019, 4:57pm

With that script, will I have to delete and re-add my things?
Should I throw in the towel and put my Z-wave things in a file instead of letting OH manage them?

Bruce_Osborne · October 17, 2019, 5:03pm

Just delete the Things from OH & re-discover. They will keep the same IDs but be updated by the binding. Your Items & rules will not need to be changed.

You do not need to exclude them from the network. Just delete from OH & re-discover. That would also be recommended if you were using manual Things files, but I am not sure the developer supports that any more for Z-Wave.

brianmichalk · October 17, 2019, 5:14pm

At first I thought, cool, but this means I’ll have to re-enter the specific device configuration. For example, I have six thermostats, and I’ll have to set the names again.
I looked at manual things file, and I’m not keen on that. It would be nice to somehow decouple the thing names into a file.
I suppose if I bound my items to the Z-wave thing channels, this would be a moot problem. I just looked, and my items are bound to channels. Don’t know what I was thinking. So, this should be easy.

Ryan_Illman · October 17, 2019, 5:42pm

I upgraded my install to the latest snapshot (2.5.0-SNAPSHOT Build #1728). Good news, my devices so far have been stable/not going offline, and the TODO error is gone. The bad news is I have some really weird addressing issues that I don’t think are openhab’s fault.

My 3 new devices are still off at the breaker, but two are showing online in openhab, and something appears to respond to commands just enough that they get kept online. And then there’s Node 27, which just showed back up in my inbox. The problem is there is no node 27 on the network. Or at least there shouldn’t be.

When I originally switched from SmartThings to OpenHab back in May, I kept having an issue with devices not being fully discovered and showing up as “Unknown Device” in the inbox. When that happened, I’d exclude them then rediscover, and they’d normally come online properly with the next ID in sequence. So the device that started out as Node 27 was excluded and re-paired and has been functioning properly as Node 28.

Does this hold true during the discovery process? I believe I tried that and it didn’t work (device shows up as unknown and doesn’t resolve within a few minutes, delete from inbox and rerun discovery, device still shows as unknown).

I think my project this evening is to rebuild my zwave network from scratch. Looks like I picked the wrong week to quit sniffing glue.

If a device doesn’t fully discover during the pairing process, what is the proper procedure (obviously excluding and re-paring is incorrect)?

5iver · October 17, 2019, 7:43pm

Manual Thing files are absolutely supported… basically a requirement for an official binding. The trouble with them is that OH dies not support updating Thing definitions, so Things need to be deleted and rediscovered to pull in an updated definition. I tried to explain here…

Labels and locations… yes, but this can be easily added into the script that I wrote, so that they will be restored. Configuration parameters… no, these will be read in from the device and updated in OH.

If they are still included in the network, the controller is reporting to the binding that the devices exist. The online/offline logic is tricky to get right and is not perfect. BUT, you should not keep device powered off, especially mains powered devices. These are routing devices and the mesh needs them. If you are not using them, then exclude the devices from the network.

… oops, sorry! 5 years ST free!

If your device is battery powered, wake it up several times to complete the discovery and initialization. Then add it in from the inbox. If it is a mains powered device, make sure it is in the device database and that the binding you are using is up to date, and also make sure that your zwave mesh is healthy… maybe take a look at a sniffer trace.

It’s actually a very good week for it!!!

Bruce_Osborne · October 17, 2019, 10:44pm

Thanks for the correction.

robmac · October 18, 2019, 5:42am

All looks very odd. Sadly sounds like Zwave is great until it is not. We all know 99% of the time adding a couple of devices is not be a big issue so it is always strange when it does.

Please could you help with some research into generic zwave issues and possibly yourself.

look for “phantom” associations. see below
has the traffic increased across some hot nodes and you are now getting latency. Any chance you could post a zniffer
then exclude the new devices from the network see if the network heels
if it does add them back in and see if it breaks

I think that possibly in the latest snapshot, the poll after command option is not working but it would need a busy poor route to be an issue and not sure why it would cause those logs. I have purposely caused excess traffic on a poor route and while the network pauses and goes bad, openHab handles it well. OpenHAB may be sending a report request after every command with almost no delay so you might have gained a busy route. I need to analyse my zniffer logs a bit more for more devices to be sure there is a general issue.

Phantom associations is a term that a friend uses to describe associations that were surely not set but appear on devices with node IDs that never existed in your network. I am busy testing for them but have not found them on my openHaq network yet. People have reported them on HC2 and various systems that use openzwave networks so it does appear to be independent of controller and possibly an issue with some devices so may not be relevant.

thanks,

Robert

chris · October 18, 2019, 7:18am

Correct - and not just a requirement either. The binding doesn’t know at all if the configuration comes from a file or the database - it just gets configuration information.

I’ve not seen any reports of this (although I’ve been very busy so may have missed them). Why do you think this isn’t working? I don’t think anything has changed recently so it would be a surprise.

ZWave has very (Very!) poor error checking so it’s not uncommon for frames to get corrupted unfortunately.

robmac · October 18, 2019, 9:21am

that is truth

robmac · October 18, 2019, 9:24am

I have seen it for just from one zniffer on one device but certainly for this one device it has requested a report immediately after the command every time. I need to get a few more devices tested and of course it could be a UI issue.

chris · October 18, 2019, 10:57am

One thing to be careful of, and that is when timing starts. The poll is timed from the time the command is queued, and not from the time it is sent. So, if there are delays in that transaction, then the poll will also be queued, and it could therefore be sent immediately after the response from the command.

robmac · October 18, 2019, 11:01am

I tried setting the poll after to disabled and still got a report request and set to a large value and it still was almost immediate. As I said I have not dug deeper yet so could be an issue with UI not setting the value.

chris · October 18, 2019, 11:43am

Just check the logs - it will be pretty clear as there is a statement logged -:

NODE {}: Polling initialised at {} seconds - start in {} milliseconds.