ZWave binding updates

chris · December 19, 2019, 7:58am

No - unfortunately this may not show up. The logs will only show information from nodes that are sending data to the controller/binding. The logs will not show all the traffic that is going on on the network - for that you need a network sniffer.

Kim_Andersen · December 19, 2019, 9:13am

This goes for the Aeotech Multisensor 6 as well. It needs to be included the same way it´s powered.

garyfree · December 19, 2019, 7:25pm

I had this and 1 other error - a comma a the begining of that line. Removing them has solved my problem. I still dont know how I have ended up with 2 /dev/tty/ACM0s though

Bruce_Osborne · December 19, 2019, 7:27pm

One have a space character on the end?

garyfree · December 19, 2019, 7:29pm

Hmm dont think so - neither appeared in the controller config on paperui…just running dmesg etc gives me 3 now…tty/ACM1 is fine
Edit - if I list /dev I get ttyACM1 only

feens · December 22, 2019, 9:04pm

@chris I’m curious…is it normal to occasionally see CAN messages? I’m just rebuilding my network trying to identify the bad actor. I.e. currently I have only a few (6) devices re-added, and I see a CAN message occasionally, but not very often (maybe one every 2-4 minutes)

adeon · December 23, 2019, 9:33pm

Hello. After upgrading to OpenHab 2.5 (running in Ubuntu 19.10), it seems that my Z-wave controller is frequently being restarted. This is what I see in events.logs

2019-12-23 22:11:08.950 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 29 to 30
2019-12-23 22:11:08.972 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 30 to 31
2019-12-23 22:11:09.001 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 31 to 32
2019-12-23 22:11:09.021 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 32 to 33
2019-12-23 22:11:09.042 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 33 to 34
2019-12-23 22:11:09.060 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 34 to 35
2019-12-23 22:11:09.073 [hingStatusInfoChangedEvent] - 'zwave:device:ab436cb5:node4' changed from ONLINE: Node initialising: REQ
UEST_NIF to ONLINE
2019-12-23 22:11:51.908 [hingStatusInfoChangedEvent] - 'zwave:device:ab436cb5:node4' changed from ONLINE to UNINITIALIZED
2019-12-23 22:11:51.930 [hingStatusInfoChangedEvent] - 'zwave:device:ab436cb5:node4' changed from UNINITIALIZED to UNINITIALIZED
 (HANDLER_MISSING_ERROR)
2019-12-23 22:11:51.931 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:ab436cb5' changed from ONLINE to UNINITIALIZED
2019-12-23 22:11:55.142 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:ab436cb5' changed from UNINITIALIZED to UNINITIALIZE
D (HANDLER_MISSING_ERROR)
2019-12-23 22:12:19.002 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:ab436cb5' changed from UNINITIALIZED (HANDLER_MISSIN
G_ERROR) to INITIALIZING
2019-12-23 22:12:19.017 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:ab436cb5' changed from INITIALIZING to OFFLINE (BRID
GE_OFFLINE): Controller is offline
2019-12-23 22:12:19.039 [hingStatusInfoChangedEvent] - 'zwave:device:ab436cb5:node4' changed from UNINITIALIZED (HANDLER_MISSING
_ERROR) to INITIALIZING
2019-12-23 22:12:19.046 [hingStatusInfoChangedEvent] - 'zwave:device:ab436cb5:node4' changed from INITIALIZING to OFFLINE (BRIDG
E_OFFLINE): Controller is offline
2019-12-23 22:12:19.069 [vent.ItemStateChangedEvent] - ZWaveSerialController_StartFrames changed from 35 to 0

This is repeating all the time. After downgrading to OpenHAB 2.4 everything seems to work fine.
Is it a known issue or I am missing something in my OpenHAB 2.5 configuration?

Bruce_Osborne · December 23, 2019, 9:39pm

Both. Did you read the Relase Notes? restdocs moved from misc to ui. Any invalid addon causes the loader to restart all addons every minute as it tries to load the invalid one(s).

Check addons.cfg and addons.config files for the culprit(s).

adeon · December 23, 2019, 10:17pm

Did you read the Relase Notes? restdocs moved from misc to ui .

I didn’t, but even if I did, I would never figure out that restdocs might somehow be related to Z-wave controller restarts. What’s more addons.cfg says Note: This is only regarded at the VERY FIRST START of openHAB. Given I’ve been upgrading openhab, it would also be difficult to find any relation to z-wave binding.
Edit: I’ve checked addons.cfg but all lines are commented out there. If I have invalid addons, how to find out which are the wrong ones? There isn’t anything in the logs.

Bruce_Osborne · December 23, 2019, 10:56pm

It’s people have found issues in the addons.config in the userdata folder.

phinnay · December 24, 2019, 4:02am

Noted, with the multitudes of folks having z-wave issues in 2.5 seemed good to share my experience - even if from a technical stand point it ‘has nothing to do with the binding’ the end result is z-wave breaks.

Even with the ‘restdocs’ issue cleared up, I’m still getting severe latency on my zwave network. This has been working reliably since a fresh 2.0 install several years back (and before that on 1.x) and nothing has changed in the hardware between 2.4 and 2.5.

Upon a reboot, z-wave works as it’s always done, but after ~20 mins we start to see 1 minute + latency between issuing a command and the desired action; also seeing events where triggering groups of zwave devices (timer or manually) will result in random devices being left on or off while others complete.

I see odd logs when this begins happening; the device thats just been triggered in the excerpt below (node 34) took over four minutes to react.

line that stand out are:

NODE 34: TID 80: Timeout at state ABORTED. 3 retries remaining.
TID 80: Transaction is current transaction, so clearing!!!""
TID 80: Transaction CANCELLED

22:40:58.247 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
22:40:58.251 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
22:41:10.238 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 34: TID 80: Timeout at state ABORTED. 3 retries remaining.
22:41:10.242 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 80: Transaction is current transaction, so clearing!!!
22:41:10.246 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 80: Transaction CANCELLED
22:41:10.249 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 34: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
22:41:10.253 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 34: notifyTransactionResponse TID:80 CANCELLED
22:41:10.258 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
22:41:10.265 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 21 03 26 01 00 25 12 D4
22:41:10.271 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 33: Sending REQUEST Message = 01 0A 00 13 21 03 26 01 00 25 12 D4
22:41:10.275 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
22:41:10.279 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 81: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 18
22:41:12.284 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 33: TID 81: Timeout at state WAIT_RESPONSE. 3 retries remaining.
22:41:12.288 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - Aborting Transaction!
22:41:12.291 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 81: Transaction ABORTED
22:41:12.296 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
22:41:12.300 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
22:41:12.305 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
22:41:12.309 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
22:41:24.296 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 33: TID 81: Timeout at state ABORTED. 3 retries remaining.
22:41:24.300 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 81: Transaction is current transaction, so clearing!!!
22:41:24.304 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 81: Transaction CANCELLED
22:41:24.308 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
22:41:24.312 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 33: notifyTransactionResponse TID:81 CANCELLED
22:41:24.316 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
22:41:24.328 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 22 03 25 01 00 25 13 D5
22:41:24.335 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 0A 00 13 22 03 25 01 00 25 13 D5
22:41:24.339 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
22:41:24.343 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 82: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 19
22:41:26.348 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 34: TID 82: Timeout at state WAIT_RESPONSE. 3 retries remaining.
22:41:26.352 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - Aborting Transaction!
22:41:26.356 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 82: Transaction ABORTED
22:41:26.361 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA

None of the devices on my network are battery powered, all hard wired Eaton or Leviton devices that have worked reliably for years.

5iver · December 24, 2019, 4:55am

Disable the daily heal, restart OH, and perform manual heals on all mains powered devices. If you still have latency, heal again. Also, search your log for “Queue full” (restart OH if you do). See…

BTW, please read up on how to use code fences.

chris · December 24, 2019, 8:26am

Please provide a full debug log and I will take a look.

This normally means there was no response to a message.

This is perfectly normal.

This means there was no response after multiple tries.

These sort of things will introduce delays in your network - if there are nodes that are not responding, then this is the inevitable endpoint.

phinnay · December 30, 2019, 5:00pm

Been reading up on other threads complaining about slow zWave performance; no sense wasting your time if it’s a topology issue Several suggestions were to confirm the zWave network and look for missing nodes - Checking HABmin, I see this:

What do the red arrows / links mean? As per this post earlier in the year, even @rlkoshak is unclear… I’d be great to have a legend to decode the map.

@chris I issued another re-initialize of the controller so will see if that helps; I am still puzzled why an update to 2.5 would manifest these issues… both your earlier comments in this thread and release notes confirm no changes to the plugin.

Thank you for taking the time on this; I’ll report back if still an issue - the debug logs requested in your previous post are from Karaf with log:set DEBUG org.openhab.binding.zwave option enabled?

chris · December 30, 2019, 5:09pm

They mean that there is only a one way connection reported from the neighbour tables. So one side reports the other is a neighbour, but the opposite is not true.

rlkoshak · December 30, 2019, 5:11pm

I’m by no means an expert on Zwave. The fact that I don’t know should not be all that surprising.

Kim_Andersen · January 4, 2020, 12:32pm

Have the daily network heal issue been fixed in 2.5 Release?

Bruce_Osborne · January 4, 2020, 12:49pm

@5iver what is your experience?

chris · January 4, 2020, 12:54pm

No - I’ve not had time to look at this.

5iver · January 4, 2020, 12:54pm

There have not been any PRs to address it and the issue is still open.