Z-wave Issues: Big delay in response and controller goes offline every day or so

TheJM · January 17, 2024, 12:35pm

Hey guys,

I recently upgraded to openHAB 4.1.1 and saw some issues after doing the upgrade. Not sure if my issues are related to the upgrade though. I’m running openHAB on a VM running Ubuntu 22.04 LTS and it’s been running great for years.

I’m running Hyper-V and my Z-wave controller is connected via this app which allows the VM to access the Hosts COM ports: GitHub - tdhoward/COMpipe: Links a serial COM port to a named pipe

My Z-wave network was lighting fast with no issues but in the last few days, I notice a big delay and or the device doesn’t respond at all. in looking at the logs, I notice that, at some points, there are no logs from the controller, like its offline but its showing online on my list of Things.

When the controller stops responding altogether, I tried restarting the z-wave binding but that doesn’t bring it back. The only things that ive found to temporarily bring the controller back are to either reboot the VM or restart the openHAB service.

The controller fell offline yesterday and I did the above procedure. It worked fine all day and I noticed that it died again somewhere between 5:15 and 7am on the 17th (today). I turned DEBUG logging on a few days ago and am uploading some logs here.

Logs: Here

Your help is much appreciated!
JM

TheJM · January 17, 2024, 12:42pm

Sorry about the breath of logs. It’s tough to identify exactly where something goes wrong and wanted to include as much info as possible.

TheJM · January 17, 2024, 1:16pm

EDIT: I uploaded 2 more logs to the folder entitled “…after restart”. I restarted the openHAB service and the controller was very delayed and then stopped responding within about 15 minutes. this might be a good place to start looking.

apella12 · January 17, 2024, 1:57pm

First to help you analyze yourself there is a log viewer here; Z-Wave Log Viewer (opensmarthouse.org)

On a quick scan I see

Node 50 never responds (GE switch)
Node 48 is getting pounded Stop your Refreshes
(as a side node Refresh on any one channel refreshes them all, so only one is needed, but still not advised)
Node 53 - reduce reporting frequency or stop refresh (couldn’t see refresh, but is acting like it)
Also recently excess reporting has been linked to orphan links. Check openhab:links orphan list/purge in the console.

TheJM · January 17, 2024, 2:18pm

Thanks for pointing this out.

Node 48 only gets a refresh ever 2 minutes because it wont report new data without it. It’s a monitor for my freezer temp. I’ve had that rule running for years but I disabled it temporarily for troubleshooting.

Node 53 is a Home Energy Monitor. again it’s been running for about a year just fine but I will disable it for troubleshooting.

I listed and purged the orphaned links. none were Z-wave.

FWIW I don’t have a Node 41 but I saw several logs related to that.

apella12 · January 17, 2024, 2:50pm

Won’t parameter 66 work for temperature reporting without refresh?

That (and Node 50) leads to the orphan “node” problem. For Node 41 on the UI try “check if failed” then “remove failed”.

I actually have these, but not currently running them in OH. Take a look at the parameters and only report on what you need. For instance I only report watts (not voltage or amps) and do a refresh at midnight to pick up a daily KWH. Only watts and KWH are linked. Also depending on the data, do not use the percentage reporting, use time only.

Edit: at a high-level delays tend to be Zwave traffic related, so I’m suggesting reducing traffic and attacking the timeouts to devices. For self-help an overview on the forum is here. [SOLVED] Unresponsive Z-Wave Network: Tools and Approaches to track down the issues - Tutorials & Examples / Solutions - openHAB Community

TheJM · January 17, 2024, 3:03pm

I set it to 60 seconds but it doesn’t actually report anything. I just assumed it was a bug with the device.

Where do I find that? I don’t have a Node 41 on my UI.

I’ll take a look at that.

Very fair point. I assumed that this related to something else and not traffic related since it had been working fine for several months on these settings. For now, ive disabled the refresh on node 48 and also unplugged the home energy monitor. if that fixes it, I’ll slowly incorporate them back in and play with the settings.

I’ll report back when I have an update in less than 24 hours.

apella12 · January 17, 2024, 3:18pm

Interesting? It is in the log, so I assumed it was in the UI. If you scan does it show up? (check ignored too). The other option is the silabs tool mentioned in the link.

It could be something new, but I don’t see it so far. Once traffic and node timeouts are eliminated, maybe it will show up.

TheJM · January 17, 2024, 4:52pm

Both node 41 and 50 are both in the Inbox and they keep showing up in the logs. Should I add them as a Thing and then find the ‘check if failed’ and ‘remove failed’ setting?

apella12 · January 17, 2024, 6:35pm

Yes. See if that works

Edit

Well I think I see something in log6 but have no idea about why. It still could be congestion. I would also disable the HEAL (this happened near the end of that)

2024-01-17 05:04:48.440 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 48: Adding return route to 1
2024-01-17 05:04:48.440 [DEBUG] [essage.AssignReturnRouteMessageClass] - NODE 48: Assigning return route to node 1
2024-01-17 05:04:48.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 48: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6a7d756a
2024-01-17 05:05:06.372 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 35 12 56 01 32 02 A1 64 00 01 DF 84 00 3C 00 01 E0 37 53 A6 23
		Died Node 53 meter report-This message was not processed
2024-01-17 05:05:41.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@557a9e5c

Based on what happens later it seems like a serial connection issue. Your Zstick connection is not typical, can there be blips?

Edit: Reviewed the Fibaro device more closely, should have asked about parameter 68 (external sensor), not 66 (Internal sensor)

TheJM · January 18, 2024, 10:21am

It worked fine yesterday but I woke up this morning and noticed a big delay again and then the controller went offline again.

I just disabled the network heal after getting the controller back online. Ill see if that helps.

I added node 41 and 50 from the Inbox and then selected ‘set device s failed’ and then ‘remove device’ from controller’ but I kept getting the below messages. Basically that the controller is busy and the remove failed.

==> /var/log/openhab/openhab.log <==

2024-01-18 05:19:13.130 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update received

2024-01-18 05:19:13.132 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_10_2 to 1 (BigDecimal)

2024-01-18 05:19:13.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_11_1 to 1 (BigDecimal)

2024-01-18 05:19:13.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored action_failed to false (Boolean)

2024-01-18 05:19:13.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored group_1 to [controller] (ArrayList)

2024-01-18 05:19:13.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update set action_remove to true (Boolean)

2024-01-18 05:19:13.134 [DEBUG] [message.RemoveFailedNodeMessageClass] - NODE 50: Marking node as having failed.

2024-01-18 05:19:13.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 324 to queue - size 1

2024-01-18 05:19:13.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2024-01-18 05:19:13.135 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 32 01 2B 80 

2024-01-18 05:19:13.135 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 32 01 2B 80 

2024-01-18 05:19:13.137 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2024-01-18 05:19:13.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 43

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored group_3 to [controller] (ArrayList)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored group_2 to [] (ListN)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored switchall_mode to 255 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_7_1 to 2 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_8_2 to 1 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_9_1 to 2 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_12_2 to 1 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_3_1 to 0 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_4_1 to 0 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored config_5_1 to 0 (BigDecimal)

2024-01-18 05:19:13.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Configuration update ignored node_id to 50 (BigDecimal)

2024-01-18 05:19:13.163 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2024-01-18 05:19:13.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.164 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 10 8B 

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 43

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 43

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2024-01-18 05:19:13.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 43

2024-01-18 05:19:13.165 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.165 [DEBUG] [message.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.

2024-01-18 05:19:13.165 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 50: Remove failed node failed as Controller Busy!

2024-01-18 05:19:13.165 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 324: Transaction CANCELLED

2024-01-18 05:19:13.166 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Got an event from Z-Wave network: ZWaveNetworkEvent

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 2 attempts left!

2024-01-18 05:19:13.166 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 324: Transaction RESET with 2 retries remaining.

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 324 to queue - size 1

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 324: Transaction not completed

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2024-01-18 05:19:13.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

==> /var/log/openhab/events.log <==

2024-01-18 05:19:13.169 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ZWaveSerialControllerSerialAck' updated to 466

2024-01-18 05:19:13.169 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialControllerSerialAck' changed from 465 to 466

2024-01-18 05:19:13.169 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ZWaveSerialControllerSerialSof' updated to 979

2024-01-18 05:19:13.169 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialControllerSerialSof' changed from 978 to 979

==> /var/log/openhab/openhab.log <==

2024-01-18 05:19:13.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2024-01-18 05:19:13.417 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 32 01 2C 87 

2024-01-18 05:19:13.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 32 01 2C 87 

2024-01-18 05:19:13.420 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2024-01-18 05:19:13.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 44

2024-01-18 05:19:13.445 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2024-01-18 05:19:13.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.445 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 10 8B 

2024-01-18 05:19:13.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 44

2024-01-18 05:19:13.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2024-01-18 05:19:13.446 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 44

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 44

2024-01-18 05:19:13.447 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.447 [DEBUG] [message.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.

2024-01-18 05:19:13.447 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 50: Remove failed node failed as Controller Busy!

2024-01-18 05:19:13.447 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 324: Transaction CANCELLED

2024-01-18 05:19:13.447 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Got an event from Z-Wave network: ZWaveNetworkEvent

2024-01-18 05:19:13.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 1 attempts left!

2024-01-18 05:19:13.448 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 324: Transaction RESET with 1 retries remaining.

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 324 to queue - size 1

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 324: Transaction not completed

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2024-01-18 05:19:13.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

==> /var/log/openhab/events.log <==

2024-01-18 05:19:13.449 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ZWaveSerialControllerSerialAck' updated to 467

2024-01-18 05:19:13.449 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialControllerSerialAck' changed from 466 to 467

2024-01-18 05:19:13.449 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'ZWaveSerialControllerSerialSof' updated to 980

2024-01-18 05:19:13.449 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ZWaveSerialControllerSerialSof' changed from 979 to 980

==> /var/log/openhab/openhab.log <==

2024-01-18 05:19:13.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2024-01-18 05:19:13.697 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 61 32 01 2D 86 

2024-01-18 05:19:13.697 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 61 32 01 2D 86 

2024-01-18 05:19:13.700 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2024-01-18 05:19:13.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 45

2024-01-18 05:19:13.725 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2024-01-18 05:19:13.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.725 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 61 10 8B 

2024-01-18 05:19:13.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2024-01-18 05:19:13.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 45

2024-01-18 05:19:13.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2024-01-18 05:19:13.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 45

2024-01-18 05:19:13.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2024-01-18 05:19:13.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 324: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 45

2024-01-18 05:19:13.727 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RemoveFailedNodeID[97], type=Response[1], dest=255, callback=0, payload=10 

2024-01-18 05:19:13.727 [DEBUG] [message.RemoveFailedNodeMessageClass] - Got RemoveFailedNode response.

2024-01-18 05:19:13.727 [ERROR] [message.RemoveFailedNodeMessageClass] - NODE 50: Remove failed node failed as Controller Busy!

2024-01-18 05:19:13.727 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 324: Transaction CANCELLED

2024-01-18 05:19:13.727 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Got an event from Z-Wave network: ZWaveNetworkEvent

2024-01-18 05:19:13.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

2024-01-18 05:19:13.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Retry count exceeded. Discarding message: TID 324: [CANCELLED] priority=Controller, requiresResponse=true, callback: 45

2024-01-18 05:19:13.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 324: Transaction completed

2024-01-18 05:19:13.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:324 CANCELLED

2024-01-18 05:19:13.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2024-01-18 05:19:13.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

TheJM · January 18, 2024, 10:42am

I also uploaded a file in the folder linked above called openhab1.18.log. I couldn’t get it to display in the Z-wave log viewer correctly but it’s basically a short clip of about a minute where I turn on and off Node 35 every few seconds. Each time it had a time delay of several seconds. IDK if this will help to isolate the issue. It’s driving me mad quite frankly. I feel like Z-wave is such a fragile and funky standard.

Link also here

TheJM · January 18, 2024, 10:44am

It’s weird, it’ll work all day just fine (like it did yesterday) and upon waking up, it’s messed up. I wonder if that has something to do with the heal?

TheJM · January 18, 2024, 11:36am

What do you mean blips? How would I go about troubleshooting this?

apella12 · January 18, 2024, 1:23pm

Blips (Non technical term ). Does the COMpipe app you are using have logs?

Also not my area, but is there another app?

I noticed that at the very bottom of openhab6.log (I’m assuming this was unattended based on the hour). What makes me think it is COMpipe is the binding continues to process your refresh commands so it seems to be running from about 05:06 am to about 06:19.40 then tries to restart, but some condition is missing (also an area I don’t know much about) and fails several times. That makes me think whatever the problem is restarting the binding won’t work. It is something outside the binding that needs to start over.

TheJM · January 18, 2024, 1:56pm

I don’t think so but I’ll look.

Interestingly restarting the openHAB service usually works which is independent of COMpipe. I wish there was an alternative but I don’t know of one that works with Hyper-V

TheJM · January 18, 2024, 2:38pm

I just rebooted Hyper-V to see if that helps. Will report back on that and if disabling the network Heal worked (that was set for 4am).

apella12 · January 18, 2024, 2:44pm

Log 1.18 shows another problem. Are you sure there is no orphan link related to that node?

The command poll at 1.5 seconds is only supposed to poll the item changed. Yours is polling all the channels and it is not finishing before you flip the switch again and all the GETs are queueing up and getting replaced, so it is unclear what state the get is going to return?

2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 339 to queue - size 7 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Transaction already in queue - removed original 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 340 to queue - size 7 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 
2024-01-18 05:25:44.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Transaction already in queue - removed original 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 341 to queue - size 7 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false. 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Transaction already in queue - removed original 
2024-01-18 05:25:44.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 342 to queue - size 7

TheJM · January 18, 2024, 2:50pm

Just so I am clear, you are wondering why it’s adding 339, 340, 341, etc. to the queue when I only pressed the switch once? I did not spam it either. waited about 5-10 seconds between presses.
take a look:

openhab> openhab:links orphan list                                              
Thing channel missing: BroadlinkRM31921681229Command -> broadlink:rm3:1ce9a40c21:command Configuration[]
Thing channel missing: BroadlinkRM31921681189Command -> broadlink:rm3:c8-f7-42-40-85-02:command Configuration[]

those 2 above are for the Broadlink Binding. Not related to Z-wave

apella12 · January 18, 2024, 3:05pm

I’d also reduce the Fibaro to about 15 minutes (or longer) and/or check if param 68 will replace the refresh. Do you really need the freezer temp every two minutes?

Then review the Node 53 parameters to what you really need. If you can get the activity down maybe you can get rid of nodes 41 and 50 as well as not strain the COMpipe.

Disclosure: I don’t much about serial communications. However, what worries me is the COMpipe baud rates. I do know that baud rates and bit rates are different so can’t be compared. What concerned me is the order of magnitude. The stated baud rates of COMpipe range from 4800 to 115200. Zwave bit rates are from 9600 to 100000. Whereas an USB2 connection can handle 480,000,000, so with USB Zwave traffic is just a blip

EDIT: Regarding Node 35, can you control via Endpoint 1 and are you using “Motion sensor enable” and “Operation mode”? it seems those last two get polled regardless. (not the big problem, but interesting)