Very slow ZWave network

FunMiles · December 26, 2020, 3:59pm

For a week now, my Z-Wave network seems to freeze periodically, with the periodicity being common and the slow-behavior time vs good behavior being over 50% of the time. Everything was working fine until then. It was fairly sudden. I did reorganize furniture and location of various peripherals around the NUC running OpenHAB. I have tried putting the zwave stick on an extension cable, as that did help enormously with my zigbee system, but it hasn’t made a difference here.
I decided, since I was going to work on my OpenHAB system, to upgrade to 3.0.
This didn’t fix anything. The behaviour is exactly the same.
Of note:

I have an Aeotec Gen 5 Z-Wave stick
When all goes well, the light on the stick changes red/blue/yellow/off at a regular rate of about 1Hz.
When the network is slow, the color changes are only once every 20s or longer.

I put the Zwave loggin on debug and here is a partial log:

2020-12-26 08:57:58.598 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 36 AD
2020-12-26 08:57:58.600 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-26 08:57:58.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 182: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-12-26 08:57:58.602 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 75: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@52ce2b69
2020-12-26 08:58:00.603 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 54: TID 182: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-12-26 08:58:00.604 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 182: Transaction is current transaction, so clearing!!!
2020-12-26 08:58:00.606 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 182: Transaction CANCELLED
2020-12-26 08:58:00.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: notifyTransactionResponse TID:182 CANCELLED
2020-12-26 08:58:00.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-12-26 08:58:00.611 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 49 01 00 25 36 BF
2020-12-26 08:58:00.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 182: Transaction event listener: DONE: CANCELLED →
2020-12-26 08:58:00.613 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 73: Sending REQUEST Message = 01 08 00 13 49 01 00 25 36 BF
2020-12-26 08:58:00.614 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-26 08:58:00.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 15: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 54
2020-12-26 08:58:00.614 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 54: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@28ce168b
2020-12-26 08:58:02.085 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@355767be
2020-12-26 08:58:02.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: Adding to device queue
2020-12-26 08:58:02.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: Added 183 to queue - size 49
2020-12-26 08:58:02.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-12-26 08:58:02.615 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 73: TID 15: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-12-26 08:58:02.617 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2020-12-26 08:58:02.618 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15: Transaction ABORTED
2020-12-26 08:58:02.620 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2020-12-26 08:58:02.621 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2020-12-26 08:58:02.623 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-26 08:58:02.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-12-26 08:58:04.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@7f2ce0c
2020-12-26 08:58:04.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Adding to device queue
2020-12-26 08:58:04.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Added 184 to queue - size 50
2020-12-26 08:58:04.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-12-26 08:58:14.620 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 73: TID 15: Timeout at state ABORTED. 3 retries remaining.
2020-12-26 08:58:14.622 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 15: Transaction is current transaction, so clearing!!!
2020-12-26 08:58:14.623 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15: Transaction CANCELLED
2020-12-26 08:58:14.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: notifyTransactionResponse TID:15 CANCELLED
2020-12-26 08:58:14.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-12-26 08:58:14.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 15: Transaction event listener: DONE: CANCELLED →
2020-12-26 08:58:14.630 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 36 AD
2020-12-26 08:58:14.631 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 36 AD
2020-12-26 08:58:14.631 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 73: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@2499534b
2020-12-26 08:58:14.632 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-26 08:58:14.633 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 73: Node Init transaction completed with response COMPLETE
2020-12-26 08:58:14.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 183: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-12-26 08:58:14.634 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 73: Node advancer - advancing to REQUEST_NIF
2020-12-26 08:58:14.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@4dd17937
2020-12-26 08:58:14.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: Adding to device queue
2020-12-26 08:58:14.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 73: Added 185 to queue - size 50
2020-12-26 08:58:14.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-12-26 08:58:16.635 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 54: TID 183: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-12-26 08:58:16.637 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 183: Transaction is current transaction, so clearing!!!
2020-12-26 08:58:16.639 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 183: Transaction CANCELLED
2020-12-26 08:58:16.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: notifyTransactionResponse TID:183 CANCELLED
2020-12-26 08:58:16.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-12-26 08:58:16.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 183: Transaction event listener: DONE: CANCELLED →
2020-12-26 08:58:16.646 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 4B D0
2020-12-26 08:58:16.646 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 54: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@6436faf4
2020-12-26 08:58:16.647 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 4B D0
2020-12-26 08:58:16.648 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-26 08:58:16.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 184: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2020-12-26 08:58:18.650 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 75: TID 184: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2020-12-26 08:58:18.652 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 184: Transaction is current transaction, so clearing!!!
2020-12-26 08:58:18.654 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 184: Transaction CANCELLED
2020-12-26 08:58:18.655 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: notifyTransactionResponse TID:184 CANCELLED
2020-12-26 08:58:18.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-12-26 08:58:18.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 184: Transaction event listener: DONE: CANCELLED →
2020-12-26 08:58:18.661 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 49 D2
2020-12-26 08:58:18.661 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 75: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@435d1d92
2020-12-26 08:58:18.662 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 49 D2
2020-12-26 08:58:20.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 54: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@355767be

Does this log give anyone any idea of what could be going on? Is there something else I should try?

stefan.oh · December 26, 2020, 4:47pm

Your log only covers app. 20 seconds. A longer log would help.
Try to attach it here as a file, that makes it easier to upload it into the Z-Wave logviewer

stefan.oh · December 26, 2020, 4:49pm

And please check if “Z-Wave Network Heal” is active in your setup. You will find that as a configuration of your Z-Wave controller.

FunMiles · December 26, 2020, 5:08pm

openhab.log (981.4 KB)
To be clear, this is the /var/log/openhab/openhab.log file. (I have a vague memory of having a separate Zwave log file in the past).
While removing the top of the file so that it would be <1MB, I saw that there are huge bursts of continuous messages that I had not seen while watching the log in a shell with tail -f Maybe you can extract something from that.

FunMiles · December 26, 2020, 5:13pm

The heal time is 2AM. So it seems to be on.

Andrew_Rowe · December 26, 2020, 5:15pm

That is an important clue. Generally moving the nodes around is discouraged but sometimes it must be done. I think what Stefan is asking is do you have nightly heal configured to run and if so, has it run since things got moved around. How many nodes in total?
You can also run heal on individual nodes.
Also consider that one ghost node will bugger things up. Make sure one of your nodes doesn’t have a dead battery

Andrew_Rowe · December 26, 2020, 5:17pm

has it run since things got moved around? If so, check logs to make sure it completed successfully.

FunMiles · December 26, 2020, 5:22pm

It must have run. The move of things around the NUC was two weeks ago.
How do check that it has completed successfully?

Andrew_Rowe · December 26, 2020, 5:24pm

check the log file
It has been two weeks since stuff got moved around, did this issue start at that time or more recently?

FunMiles · December 26, 2020, 5:28pm

The trouble started shortly after. I did not record exactly when it happened.
In the logs I see:

NUC% grep -i heal /var/log/openhab/openhab.log*
/var/log/openhab/openhab.log:2020-12-26 10:23:57.107 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 16 hours time.
/var/log/openhab/openhab.log.4:2020-12-26 08:55:22.391 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 18 hours time.
/var/log/openhab/openhab.log.4:2020-12-26 10:14:09.965 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 16 hours time.

That’s it. Do I need to look for some other indication?

Marcin_J · December 26, 2020, 5:29pm

Ensure that there is no unavailable devices. This slow down the network a lot. And maybe some of the devices have just poor network range?

Andrew_Rowe · December 26, 2020, 5:39pm

On 2.5. you had HabMIN available which had some special zwave tools included. Now on 3, I think HabMIN went away but the functionality is included in the Main UI. Can’t help there because I am still on 2.5
As Marcin mentioned, one bad node can ruin the party. How many battery powered devices do you have, how many mains powered devices?

I think when it completes, there is an entry in the log indicating so. When it does not complete, it simply hangs and there is no such message. I’m going from memory thou so…

I’m betting you have a node with a dead battery or one which is out of range or the heal has not completed successfully. The heal is design to rewrite the routes between nodes, moving stuff around requires a successful heal.

keep digging

FunMiles · December 26, 2020, 5:46pm

I have 50 devices. 2 battery powered ones. They don’t seem to appear in the log in any bad way.
I could remove one of them as it is not really used anymore.
One thermostat is not responding but that has been that way for months and I haven’t had any consequences from it.
I can clean up a few nodes that are of no use but still on the stick.

Andrew_Rowe · December 26, 2020, 5:51pm

do that yes

Andrew_Rowe · December 26, 2020, 5:54pm

After you clean out your unused nodes, I think you can trigger a heal manually, do so and watch the logs as thing progress. It takes a few minutes to run successfully but keep an eye on it

FunMiles · December 26, 2020, 6:03pm

How do I force a heal manually?
BTW in OH3, trying to view the ZWave network gives a blank page.
I did a soft reset. The network is still very slow.

Andrew_Rowe · December 26, 2020, 6:12pm

in OH3… I don’t know, sorry

sihui · December 26, 2020, 6:26pm

On your device Thing, go all the way down to the bottom:

sihui · December 26, 2020, 6:28pm

You should see your network again after the nightly heal:

FunMiles · December 26, 2020, 6:44pm

Unfortunately, I am not getting the same thing as you:

There’s no Heal option in the stick page.

PS: The heal option appears on other devices, not on the stick’s page. Does it do the same thing as a heal of the whole network? Clicking on one device’s heal option does not seem to help anything.

PPS: Trying heal on the closest node to the NUC/ZWave stick seems to have awoken a bunch of actions on the stick and it seems to be flashing as expect during normal operations. Seeing some of the debug messages, I ended up unplugging a smart strip (node 55 in the logs) and so far the network is back to normal. Will post further updates.