Z-Wave controller offline after power failure

Add-ons Bindings
1

I had a power failure in my house last night and after that my Z-wave controller is offline. I have tried to restart/soft reset etc but no luck. the message: “Attempting to add listener when controller is null” looks really strange. Anyone that knows what is going on?

2021-08-28 11:54:18.768 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:659621590a with scan time of 60
2021-08-28 11:54:18.768 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:659621590a
2021-08-28 11:54:18.768 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2021-08-28 11:54:18.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2021-08-28 11:54:18.783 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:659621590a.
2021-08-28 11:54:18.787 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node28.
2021-08-28 11:54:18.789 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node7.
2021-08-28 11:54:18.789 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node9.
2021-08-28 11:54:18.790 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node4.
2021-08-28 11:54:18.791 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node8.
2021-08-28 11:54:18.791 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node27.
2021-08-28 11:54:18.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node29.
2021-08-28 11:54:18.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node6.
2021-08-28 11:54:18.793 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node3.
2021-08-28 11:54:18.794 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node23.
2021-08-28 11:54:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node24.
2021-08-28 11:54:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node26.
2021-08-28 11:54:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node25.
2021-08-28 11:54:18.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node2.
2021-08-28 11:54:18.799 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node20.
2021-08-28 11:54:18.802 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node21.
2021-08-28 11:54:18.802 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node22.
2021-08-28 11:54:18.803 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node34.
2021-08-28 11:54:18.804 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node37.
2021-08-28 11:54:18.805 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node36.
2021-08-28 11:54:18.806 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node30.
2021-08-28 11:54:18.806 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node31.
2021-08-28 11:54:18.808 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node33.
2021-08-28 11:54:18.808 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node35.
2021-08-28 11:54:18.809 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node17.
2021-08-28 11:54:18.810 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node16.
2021-08-28 11:54:18.810 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node32.
2021-08-28 11:54:18.811 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node19.
2021-08-28 11:54:18.812 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node18.
2021-08-28 11:54:18.814 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node13.
2021-08-28 11:54:18.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node12.
2021-08-28 11:54:18.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node15.
2021-08-28 11:54:18.817 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node14.
2021-08-28 11:54:18.817 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node11.
2021-08-28 11:54:18.818 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:659621590a:node10.

If I try to edit the information on the thing, for example the serial port, I get the following debug output and “No bridgeUID found in getConfigDescription”:

==> /var/log/openhab/openhab.log <==
2021-08-28 12:15:26.285 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:659621590a
2021-08-28 12:15:26.301 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to FB 4E 72 CF 34 C1 9D 92 70 08 B1 1F 18 B0 AB DD (String)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored port to /dev/ttyACM0 (String)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2021-08-28 12:15:26.310 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2021-08-28 12:15:26.311 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2021-08-28 12:15:26.311 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2021-08-28 12:15:26.311 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2021-08-28 12:15:26.400 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:659621590a

Platform information: OH 3.1 run in a Docker container on a NUC, Ubuntu 20.4.1 and Java: openjdk version “11.0.12” 2021-07-20 LTS
OpenJDK Runtime Environment Zulu11.50+19-CA (build 11.0.12+7-LTS)
OpenJDK 64-Bit Server VM Zulu11.50+19-CA (build 11.0.12+7-LTS, mixed mode)

2

restarted host? openHAB? or zwave controller? Unsure what you are saying… anyhow, I understand openHAB is running in a docker, how is the controller physically connected?

This might have to do with a problem with the serial library used in openHAB, check this issue
https://github.com/openhab/openhab-core/issues/1842
sorry, it is a long thread but towards the bottom, a contributor from the NRJavaserial project describes the issue in great detail
TL DR: NRJavaserial is leaking files which on power loss could block serial port

1 Like
3

Thanks, I will read through the thread and see what I can find out!

I have restarted the host and OH several times with/without the Aeotec physically connected to the USB-port (/dev/ttyACM0). I also tried a “soft reset” of the z-wave controller in the things-page. Finally also tried to reinstall the binding but nothing helped.

4

Also there is discussion in the forum here, I think this is related to the github issue.

5

Tried every workaround I could find but without any luck. Using a separate bit of hardware and using ser2net could be an option but not sure I want to go that route now.

As a last resort, I tried moving the the usb-controller to a port on the back of the NUC and for whatever reason everything came online and it all started to work again, even though the serial port is still /dev/ttyACM0. Crossing my finger this will work until there is a more long-term solution in NRJavaserial available since there are only a limited number of usb-ports available on the NUC :sweat_smile: