Cancelled Frames after adding new Z-wave devices

chris · October 18, 2019, 9:17pm

It would be good to see at least the start of this transaction. If you also have the sniffer log for the same time it might be helpful since I don’t really know why this is reported. I don’t think anything has changed in the binding that should have caused this as there haven’t been any real changes for a while, but who knows…

robmac · October 20, 2019, 3:34pm

The log was created during a startup. I have tried to create a new log during a start with zniffer close to controller so all controller traffic is collected.

I end up with huge logs in no time due to the huge amount of traffic during startup.

Can see same todo lines but it is a long way down the log so a lot of lines prior. Any ideas how I can be sure to give you enough lines as all before the issue is far to many lines to post.

brianmichalk · October 27, 2019, 6:49pm

Grrr. I solved the problem about a week ago by hard resetting the controller, and doing a factory reset and include on all of the Z-wave devices.
Yesterday, a balky switch had to be physically disconnected during an event, and that threw the Z-wave network back into disarray. The switch has now been reconnected, and my network shows red arrows (after an overnight heal). I’m getting nodes dropping offline again, and the error messages are back:
TODO: Implement Application Update Request Handling of New ID Assigned (64).
2019-10-27 13:42:30.955 [ERROR] [lmessage.RequestNodeInfoMessageClass] - Request node info not placed on stack due to error.

chris · October 29, 2019, 9:51am

This typically means the controller has no buffers available to support sending more frames. It’s hard to know why this is, but it can be caused by a device flooding the network for example.

brianmichalk · October 29, 2019, 1:53pm

I have a suspicion it’s a bad node. I just don’t know which one. What should I be looking for?

sihui · October 29, 2019, 3:28pm

Create a DEBUG log and look for timeouts:
https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

robmac · November 4, 2019, 5:27pm

Get a zniffer. Look for explorer frames to start. Fix those then look for routes that fail but have a working route.

May not be a failed. Mine was a phantom association as I guessed it would be and leaving zniffer logs running allowed me to find it.

brianmichalk · November 4, 2019, 6:35pm

I do have phantom nodes. They have routes that I think others are trying to use. I’ve sort of looked at a zniffer. This is the one that a person modifies? Can it help with deleting the phantom nodes, or is that still something that only a Windows machine can do?

robmac · November 4, 2019, 8:24pm

What type of device do you have phantoms on?

A zniffer is just a flashed UZB3 available from many places. You can use either a bridge or static controller that matches your frequency and flash with the zniffer firmware.

The zniffer app is indeed windows only so you need a way to run a windows application that is portable.

This link https://forum.fibaro.com/topic/29923-tutorial-z-wave-diagnostics-with-pc-controller-and-zniffer/?tab=comments#comment-147847 is a good guide.

ccutrer · November 29, 2019, 4:16pm

Since updating for 2.5.0 S1555 to 2.5.0 M5, about once a day I start getting Implement Application Update Request Handling of New ID Assigned very often. A restart of the zwave bundle fixes it - until the next day. I have ~145 zwave nodes, but zero phantom routes or dead devices in the controller or OpenHAB. When it’s in this state, zwave commands and updates are often lost and/or laggy. I’ve turned on debug logging, and if I remove and re-add the thing for the node requesting the update (looking at the dest field of the previous message before the error), it just starts being another node causing it.

ccutrer · December 2, 2019, 3:10pm

And… this is now an everyday thing. I have to restart my z-wave bundle every morning. These are the timestamps of the first Implement Application Update Request log message every day for the past four days:

2019-11-29 02:23:48.166
2019-11-30 02:34:47.775
2019-12-01 02:01:18.826
2019-12-02 02:28:07.276

I don’t have any rules or cron jobs that I explicitly run in that time frame (I have one that runs at 03:00). While looking for these timestamps, I did find these in the log:

2019-11-29 02:30:26.957 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 187: Not initialized (ie node unknown), ignoring message.
2019-11-29 05:54:48.670 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 05:54:49.631 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:30.543 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:30.556 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:31.553 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:31.649 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:31.675 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 08:38:31.700 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 235: Not initialized (ie node unknown), ignoring message.
2019-11-29 09:18:23.972 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 50: Not initialized (ie node unknown), ignoring message.
2019-11-29 09:18:24.233 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 50: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:12.235 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:12.292 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:12.500 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:12.539 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:12.550 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:13.020 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:13.027 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 236: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:13.040 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 08:04:13.325 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 188: Not initialized (ie node unknown), ignoring message.
2019-11-30 13:27:42.330 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 44: Not initialized (ie node unknown), ignoring message.
2019-11-30 13:27:43.012 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 44: Not initialized (ie node unknown), ignoring message.
2019-11-30 13:27:43.202 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 44: Not initialized (ie node unknown), ignoring message.
2019-11-30 13:29:52.940 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 45: Not initialized (ie node unknown), ignoring message.
2019-12-01 04:06:27.855 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 04:06:27.874 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 04:06:27.992 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 05:33:03.922 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 4: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.730 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.738 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.762 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.799 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.822 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:53.908 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.
2019-12-01 23:44:57.535 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 128: Not initialized (ie node unknown), ignoring message.

Which initially gave me pause, except that I’ve never had nodes with IDs 187, 235, or 236 (the highest node id I have is 179).

sihui · December 2, 2019, 3:48pm

This looks like the nightly heal (default is 2 AM) is causing this. Try disabling it to see if that helps.

5iver · December 2, 2019, 5:41pm

After disabling heal, restart OH to clear the hung threads