OH 3 - Z-wave Stick resetting when switching tabs in the controller-thing or excluding devices

Chrishab · January 1, 2021, 7:57pm

Hi,

Coming from a well-working OH 2.5 installation I encountered several issues with the Z-Wave binding.

I am running on a Raspi 4 with an USB 2 hub due to the Aeonstick-issue.

After migrating to OH 3 I cannot exclude devices anymore or use the tabs on the thing (Thing | Channels | Code) as these actions result in a reset of the Zwave controller and all Zwave devices are being re-initialized:

2021-01-01 20:40:19.404 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:512' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): @text/zwave.thingstate.controller_offline ["/dev/ttyACM0"]
2021-01-01 20:40:19.408 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node74' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.410 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node72' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.412 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node71' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.414 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node78' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.418 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node73' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.424 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node77' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.433 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node83' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.434 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node84' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.441 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node82' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.444 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node70' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.446 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node49' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.449 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node45' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.451 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node76' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.453 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node56' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.455 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node59' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.458 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node57' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.460 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node60' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.463 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node64' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.465 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node65' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.467 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node20' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.470 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node27' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.472 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node61' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.473 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node24' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.474 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node26' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.476 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node25' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.477 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node68' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.478 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node18' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.480 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node19' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.481 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node16' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.482 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node6' changed from ONLINE: Node initialising: REQUEST_NIF to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.484 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node58' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.485 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node28' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.486 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node33' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:19.487 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:512:node17' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-01-01 20:40:24.436 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:512' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
==> /var/log/openhab/openhab.log <==
2021-01-01 20:40:29.452 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-01-01 20:40:29.454 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2021-01-01 20:40:29.461 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 78: Not initialized (ie node unknown), ignoring message.
2021-01-01 20:40:29.464 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 78: Not initialized (ie node unknown), ignoring message.
==> /var/log/openhab/events.log <==
2021-01-01 20:40:33.672 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:512' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

Any advice of what I can do? Remove the controller and re-add?

On the thing I can switch between the “Thing” and “Channels” tab with no problem, but as soon as I click on “Code” and then any of the other 2 tabs the same reset happens.

Enabling the Zwave DEBUG mode doe snot bring much more info:

2021-01-01 20:54:41.068 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:512' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): @text/zwave.thingstate.controller_offline ["/dev/ttyACM0"]
2021-01-01 20:54:41.076 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Stopping ZWave network
2021-01-01 20:54:41.077 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller
2021-01-01 20:54:41.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager

Help please

Bruce_Osborne · January 1, 2021, 8:02pm

Are you sure the device on the Pi 4 is /dev/ttyACM0 ?
What does the command dmesg | grep tty output?

Chrishab · January 1, 2021, 8:04pm

Pretty sure, yes. Worked the same in OH 2.5.
Output:

[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:04:52:21 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  usb-storage.quirks=152d:0579:u dwc_otg.lpm_enable=0 console=tty1 root=/dev/sda1 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.001559] printk: console [tty1] enabled
[    1.189372] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 29, base_baud = 0) is a PL011 rev2
[    6.208624] cdc_acm 1-1.3.2:1.0: ttyACM0: USB ACM device

Bruce_Osborne · January 1, 2021, 8:05pm

Sorry, I thought perhaps you updated to a Pi 4 at the same time as OH upgrade.

Chrishab · January 1, 2021, 8:05pm

Switching the tabs: I noticed that switching from “Code” to any other tab executes a “save” on the Thing.
Maybe that is triggering the reset.

Leaves me with the inability to Exclude devices…

Bruce_Osborne · January 1, 2021, 8:06pm

Did you have any bindings defined ini OH2 that are not (yet?) in OH3? That would cause the controller to go offline every minute.

Chrishab · January 1, 2021, 8:09pm

No, I made sure of that. The controller is working fine (except for some weird thing-issues that I did not figure out yet: OpenHAB 3 zwave items/channels only updating after saving the item).

Only when clicking on “Exclude” it will reset.
Even clicking on “Synchronize Network” (even though not applicable) will trigger the reset.

I am on the latest snapshot btw: 3.1.0-SNAPSHOT - Build #2109

stefan.oh · January 2, 2021, 10:38am

I am on OH3.0 stable, have a different controller but see the same issue: when changing tab from “Code” to “Thing” or “Channels” the controller goes offline and online again a moment later.
Log shows

2021-01-02 11:34:18.736 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /js/3.app.js java.io.IOException: Close org.eclipse.jetty.server.HttpConnection$SendCallback@e468d5[PROCESSING][i=HTTP/1.1{s=200,h=2,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2391b9] in state PROCESSING
2021-01-02 11:34:47.292 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-01-02 11:34:47.300 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

chris · January 2, 2021, 10:44am

@ysc is this right? Is this needed even?

It seems like this would be a change in the way the system works from OH2.

I can take a look at the binding to see if we can reduce the number of restarts - the binding currently does a restart if certain configuration is updated, but is it really necessary to update the configuration from the UI each time a tab is changed?

ysc · January 2, 2021, 11:25am

@chris the offending code is there:

openhab-webui/thing-details.vue at abcc52e7cc4bc599d4a4c1c3a8d10b4af78b6779 · openhab/openhab-webui · GitHub

The fromYaml method parsing the YAML is supposed to return true if the thing becomes “dirty” and saves it in that case to reload a clean state, in order to avoid problems with the channel list/linking - for example if you use the code view to add channels manually then immediately try to link them.

It seems that this dirtyness check doesn’t work well and the thing is always reported dirty when coming back from the code tab. It should be fixed and possibly made smarter i.e. detecting if the change is in configuration or the channels or both.

Chrishab · January 2, 2021, 12:30pm

Could you also check what happens when clicking “Exclude Devices”?
Does this also trigger a reset?

chris · January 2, 2021, 12:44pm

No - it won’t. But as I said above, if the UI is sending updates to other things, then the controller will be reinitialised.

Chrishab · January 2, 2021, 1:00pm

Hi @chris, in my case it does. So I cannot exclude devices at the moment.
What kind of log do I need to capture to find the root cause?

chris · January 2, 2021, 1:07pm

I doubt it, and I’m not sure how you can tell.

Maybe I wasn’t clear though - due to the fact that all configuration is being sent, when you are only changing the exclude option, THE OTHER configuration parameters will cause the controller to reinitialise.

stefan.oh · January 2, 2021, 1:22pm

No it doesn’t, confirming Chris’ statement

chris · January 2, 2021, 1:24pm

Note that I submitted a fix that will hopefully solve this an hour or two ago and am just waiting for CI to build it, but there’s a bit queue at the moment so it might take a while.

Chrishab · January 2, 2021, 3:17pm

Thank you @chris,
I will wait for the new snapshot, test again and post the results.

chris · January 2, 2021, 4:18pm

It should be available now - at least the CI task has completed.

Chrishab · January 2, 2021, 4:26pm

yes, I noticed that.
I am a bit unsure how to test that. I upgraded the binding in karaf via

bundle:update org.openhab.binding.zwave https://ci.openhab.org/job/openHAB-ZWave/lastSuccessfulBuild/artifact/target/org.openhab.binding.zwave-3.1.0-SNAPSHOT.jar

But I still encounter the same issue. Do I have to clear caches?

chris · January 2, 2021, 4:49pm

Do a list command in the console to double check what version is running. If it’s definitely the one built this afternoon, then please post a log so I can take a look at what’s happening.