ZWaveSerialHandler keeps trying to reach the ignored devices

tinman · December 28, 2018, 4:18am

hi, i am using the aeotec z-stick as a bridge in openhab 2.4 on a raspberry pi 3b. i removed a few devices but they keep coming back, i have just been ignoring them. some posts suggest to use the zensys tool. but i actually don’t mind. however, since a few days ago the on-line devices response time have been slowing, to like, over 10 seconds delay. i also upgraded from 2.3 and 2.4 a few days ago, not sure if it’s just coincidence or some new behaviors in 2.4. so i decided to debug and troubleshoot.

what i see in debug log is that the binding keeps trying to reach the removed and ignored nodes: 11, 16, 17, 18 and 19. is there a way to stop it?? or i have to use the zentool?

https://1drv.ms/u/s!AgqgZIHcLVH6jrIdpR-2jl7pUU9fnw

thanks!!

chris · December 28, 2018, 10:40am

The protocol side of the binding (is the side that works with the ZWave controller at the protocol level) will always try to communicate with the devices that the controller says are available on the network to try and find out what these devices are.

By selecting the ignored state in the inbox, you have told the OH side of the binding not to create things from these nodes - that will not impact the low level communications in the protocol stack.

tinman · December 28, 2018, 6:18pm

i downloaded the zen tool and tried to remove node 16,17,18 and 19. but it said failed.

initially i had the 4 devices setup and all good in my controller for testing. then i brought the 4 devices to my friend’s house, used his controller to exclude and include the 4 devices to his network. but now, my controller is having a hard time forgetting them and really slowing down the network.

so i went back to openhab to try my luck again.

when i marked the device as failed. it says it is live
when i remove it from controller, it says it’s not found
when i delete it, it will reappear in inbox while the controller still keeps trying to reach it in the background.

what else can i do? thanks again!

2018-12-28 12:59:18.804 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling…

2018-12-28 12:59:18.807 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling deferred until initialisation complete

2018-12-28 13:00:05.703 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 16: ZWaveCommandClassTransactionPayload - send to node

2018-12-28 13:00:05.706 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, endpoint 0

2018-12-28 13:00:05.707 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported

2018-12-28 13:00:05.708 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured

2018-12-28 13:00:05.709 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@193d68e

2018-12-28 13:00:05.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue

2018-12-28 13:00:05.714 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 238 to queue - size 9

2018-12-28 13:00:05.732 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false

2018-12-28 13:00:05.735 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 16: Creating empty message of class = SendData (0x13), type = Request

2018-12-28 13:00:05.740 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 08 00 13 10 01 00 25 E6 36

2018-12-28 13:00:05.775 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.

2018-12-28 13:00:05.781 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction not completed

2018-12-28 13:00:10.167 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 230, Status = Transmission complete, no ACK received(1)

2018-12-28 13:00:10.175 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-12-28 13:00:10.176 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: CANCEL while sending message. Requeueing - 2 attempts left!

2018-12-28 13:00:10.178 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue

2018-12-28 13:00:10.179 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 238 to queue - size 9

2018-12-28 13:00:10.197 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false

2018-12-28 13:00:10.199 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 16: Creating empty message of class = SendData (0x13), type = Request

2018-12-28 13:00:10.204 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 08 00 13 10 01 00 25 E7 37

2018-12-28 13:00:10.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction not completed

2018-12-28 13:00:10.237 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.

2018-12-28 13:00:10.242 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction not completed

2018-12-28 13:00:14.628 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 231, Status = Transmission complete, no ACK received(1)

2018-12-28 13:00:14.634 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-12-28 13:00:14.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: CANCEL while sending message. Requeueing - 1 attempts left!

2018-12-28 13:00:14.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue

2018-12-28 13:00:14.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added 238 to queue - size 9

2018-12-28 13:00:14.652 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false

2018-12-28 13:00:14.654 [TRACE] [nhab.binding.zwave.internal.protocol.SerialMessage] - NODE 16: Creating empty message of class = SendData (0x13), type = Request

2018-12-28 13:00:14.660 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 08 00 13 10 01 00 25 E8 38

2018-12-28 13:00:14.675 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction not completed

2018-12-28 13:00:14.689 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.

2018-12-28 13:00:14.693 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction not completed

2018-12-28 13:00:19.204 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 232, Status = Transmission complete, no ACK received(1)

2018-12-28 13:00:19.210 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-12-28 13:00:19.211 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Retry count exceeded. Discarding message: TID 238: [CANCELLED] priority=Poll, requiresResponse=true, callback: 232

2018-12-28 13:00:19.212 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false

2018-12-28 13:00:19.213 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent

2018-12-28 13:00:19.214 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Setting OFFLINE

2018-12-28 13:00:19.218 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is DEAD

2018-12-28 13:00:19.219 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Node is DEAD.

2018-12-28 13:00:19.222 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent

2018-12-28 13:00:19.223 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Setting OFFLINE

2018-12-28 13:00:19.227 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is DEAD

2018-12-28 13:00:19.229 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 238: Transaction completed

2018-12-28 13:00:19.230 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:238 CANCELLED

2018-12-28 13:00:19.233 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-12-28 13:00:19.238 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 16: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@98ddca

2018-12-28 13:00:46.327 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update received

2018-12-28 13:00:46.334 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update set action_failed to true (Boolean)

2018-12-28 13:00:46.336 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 16: Marking node as having failed.

2018-12-28 13:00:46.404 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 16: Remove failed node failed as node not found

2018-12-28 13:00:46.425 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNetworkEvent

2018-12-28 13:00:51.717 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update received

2018-12-28 13:00:51.723 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update set action_remove to true (Boolean)

2018-12-28 13:00:51.726 [DEBUG] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 16: Marking node as having failed.

2018-12-28 13:00:51.779 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 16: Requesting IsFailedNode status from controller.

2018-12-28 13:00:51.794 [ERROR] [rotocol.serialmessage.RemoveFailedNodeMessageClass] - NODE 16: Remove failed node failed as node not found

2018-12-28 13:00:51.798 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNetworkEvent

2018-12-28 13:00:51.859 [DEBUG] [al.protocol.serialmessage.IsFailedNodeMessageClass] - NODE 16: Is currently marked as healthy by the controller

2018-12-28 13:00:51.861 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent

2018-12-28 13:00:51.862 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Setting ONLINE

2018-12-28 13:00:51.867 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is ALIVE

2018-12-28 13:00:51.868 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Node is ALIVE. Init stage is PING.

2018-12-28 13:00:51.873 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveNodeStatusEvent

2018-12-28 13:00:51.874 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Setting ONLINE

2018-12-28 13:00:51.879 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - NODE 16: Node Status event - Node is ALIVE

tinman · December 28, 2018, 8:21pm

wow, unbelievable! i was playing with the zen tool a bit more and decided to give the ‘replace node’ a try, turned out that’s a fix!! so instead of just ‘remove’, which will fail. i did ‘replace’ first, then abort when it asked to press the button. the node then gets moved (or re-added) to the bottom of the list. and from there, i ‘remove’ it, and… it just removed instantly! i was a bit skeptical they were really removed, so i went back to openhab, the things don’t show up in inbox anymore, and no trace of them in the log file. spectacular!!

5iver · December 29, 2018, 4:42am

Zensys Tools will not allow you to use ‘Remove Failed Node’ until it is marked as failed. To do this, you need to send a NOP (you need to type the node number in the text box first). You can then do the isFailed check, and Remove Failed Node. It’s a bit fiddly at times, and I’ve had to retry, or even shutdown the app, unplug/replug the stick, and try again to get it to work.

Looks like you found a way, but this may help others reading your post.