Openhabian + RPi4 + Zwave Gen5 falls offline on restart

You’ve gone well beyond my technical expertise. I’ve spent more time trying to avoid hard resets than figuring out what happens after them. It’s possible that the other Gen5/5+ users out there have taken the same approach, which is why this hasn’t come up (to my limited knowledge).

I think I’ve only had one hard reset with OH3, due to my UPS battery needing to be replaced, so I agree that you can’t guarantee it won’t happen. But at the same time, the probability with a UPS is low enough that I’m not concerned about it.

Don’t get me wrong: if I ran into this as you have, I’d also have a burning need to figure out the problem. That’s our curse. :wink:

Sorry I can’t help more!

There are only three INFO level messages in the openhab log for a successful zwave startup and I see all of them in your code snippets, so this must be one (hard restart) that worked?

2023-04-30 18:09:56.493 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-04-30 18:10:01.664 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2023-04-30 18:10:01.666 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

To get more of what is going on you will need to set the Zwave binding in Debug before you pull the power. Like @rpwong I have an UPS, so have not played with hard restarts, but there is lots of diagnostics at the debug level. I’d advise reading the section in the zwave binding docs at the bottom “when things do not go as planned” , create a separate zwave logger (This will make it esier to pick out the zwave messages) and note the Debug log viewer for an easier to read output.

Edit: Skip the log viewer in this case. Just ran a startup log and only one line.

Bob,

Thanks. I did not show the whole log of hard and soft reset attempts. I was trying to show what working and non-working bringups look like in my testbed.

I’ve turned on Debug and now testing a couple theories. Will post when I have something repeatable to share.

I agree a UPS is a good thing and I have a UPS on my production system, but even in production I see the UPS more as a crutch than a solution. Inevitably there will be a scenario where the PI loses power or hangs and a hard reset is the only option. It usually happens when I’m out of town and can’t really walk someone through a complicated cold start.

That was unclear to me. So the non-working only got to “attempting to add listener”? If yes this is what is supposed to happen after that. So I suspect it is a still a problem with the serial port.

2023-01-14 13:52:30.032 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-01-14 13:52:30.129 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-01-14 13:52:30.132 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:dc53d2dcef.
2023-01-14 13:52:30.499 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:dc53d2dcef:node3.
2023-01-14 13:52:30.538 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:dc53d2dcef:node18.
2023-01-14 13:52:30.557 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:dc53d2dcef:node20.
>snip<
2023-01-14 13:52:35.171 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2023-01-14 13:52:35.208 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2023-01-14 13:52:35.218 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2023-01-14 13:52:35.221 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2023-01-14 13:52:35.224 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2023-01-14 13:52:35.293 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2023-01-14 13:52:35.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2023-01-14 13:52:35.295 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

I don’t disagree it’s related to serial port handling. I’ve now tried about 50 cold and warm starts.

When it works I get this sequence:

2023-05-18 15:07:04.459 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.

2023-05-18 15:07:04.461 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.

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

2023-05-18 15:07:04.452 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:3070fe8bd9’ changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING

2023-05-18 15:07:04.467 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:3070fe8bd9’ changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

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

2023-05-18 15:07:09.495 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port ‘/dev/zwave’

2023-05-18 15:07:09.528 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread

2023-05-18 15:07:09.537 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive

2023-05-18 15:07:09.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2023-05-18 15:07:09.547 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller

2023-05-18 15:07:09.580 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller

When it doesn’t work it never reports “Connecting to serial port”

I’m searching for a pattern on what’s next. Sometimes when I open the OFFLINE serial binding by changing the serial port name from the /dev/ttyACM0 to /dev/zwave or back again, the binding manages to reinitialize the serial port. Sometimes when I use systemctl to restart openhab.service that triggers the binding to reconnect. In all cases /dev has the USB device and a udev symlink to the device.

Running out of ideas on what else to try. What’s the best way to get the developer’s attention to see if this problem is interesting or not?

Also FWIW I verified my PI firmware VL805 is current version 000138C0.

These observations do not seem in sync. Edit: Never mind misread the double negative in the first quote. :confused:

I do not have a not working start up Debug, but look earlier in the debug log there may excerpt for messages related to serial I/O

2023-01-14 13:51:55.446 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : New service tracker for SerialPortManager, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.transport.serial.SerialPortManager), initialReferenceFilter (objectClass=org.openhab.core.io.transport.serial.SerialPortManager)
2023-01-14 13:51:55.449 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : dm SerialPortManager tracker reset (closed)
2023-01-14 13:51:55.456 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : dm SerialPortManager tracker opened
2023-01-14 13:51:55.459 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : registering service listener for dependency SerialPortManager
2023-01-14 13:51:55.462 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Changed state from disabled to unsatisfiedReference
2023-01-14 13:51:55.465 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Component enabled
2023-01-14 13:51:55.467 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : ActivateInternal
2023-01-14 13:51:55.470 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:55.473 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:55.476 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Activating component from state unsatisfiedReference
2023-01-14 13:51:55.479 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:55.482 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:55.486 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Dependency not satisfied: SerialPortManager
2023-01-14 13:51:55.489 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Not all dependencies satisfied, cannot activate
2023-01-14 13:51:56.019 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=490, service.bundleid=271, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=295} (enter)
2023-01-14 13:51:56.027 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : ActivateInternal
2023-01-14 13:51:56.050 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:56.054 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:56.057 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Activating component from state unsatisfiedReference
2023-01-14 13:51:56.060 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:56.063 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Querying state unsatisfiedReference
2023-01-14 13:51:56.066 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.0.0.202301121226 (265)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(289)] : Changed state from unsatisfiedReference to satisfied

(As an aside please use the </> for your code and forget about the events log.)

I’m no expert by any standard, but with several years on OH and the forum, there have been problems with the serial port. It is not a zwave issue, but OH core and likely related to nrjavaserial. Mostly I thought the problem with a stale lock file had been resolved, but maybe with your hard shutdown it is not. It has been a problem that some have developed an alternative. This thread might be worth reviewing for background. OH3.X Alternative Java serial provider - Tutorials & Examples / Solutions - openHAB Community.

Sorry for the confusion.

Your guess about serial ports sounds plausible. I’ll spend some time looking at that. Perhaps there’s a way to set up a script or rule to run a Java or Python program to clear lock files when the Zwave binding starts.

This is a bit frustrating. I’ve been working for six months now on integrating OH into controlling climate in one house. I’ve been down one cul-de-sac after another because I just can’t get the “last” piece to talk or be stable. I’m designing out an AMX system and it’s giving me more respect for Savant every day.

I can’t tell from your messages if it works 100%, but restarting OH after a hard shutdown should work pretty well. That’s kinda the go-to “solution”. For instance after an upgrade (like from M1 to M2) a restart clears all sorts of problems.

I will run some more tests, but I don’t know that I’m seeing 100% recovery from OH restart. I guess I’d have to detect a cold boot and then restart OH a second time. Sounds like a recipe for an infinite reboot loop if I get the cold boot flag wrong.

Do you know if

sudo systemctl restart openhab.service

also restarts the JVM? I’ve been down this track before and nothing good happens when Java is supposed to talk to a physical port.

I tend to focus on zwave issues I see in the forum as I have a modicum of experience on it and have studied the binding code a bit. I’ll ping the forum guru for a comment @rlkoshak He knows everything

I’m looking at the java code for the binding and I have a new theory to test.

It looks like the error is happening before the binding tries to open the serial port

I think this log shows what’s going on. I hard reset with the serial port configured as “/dev/zwave”.

Zwave did not come back ONLINE. I reconfigured first to “/dev/zwav” just to force the updater to run. Log shows ZwaveSerialHandler tried to start, but failed in getConfigDescription twice.

Then I set back to “/dev/zwave”. Same thing. Next to “/dev/ttyAC” and then back to “/dev/zwave”. Finally I set it to “/dev/ttyACM0” and this try succeeded. Not on the log, but I subsequently set it back to “/dev/zwave” and that also succeeded.

There might be a problem with serial support, but it looks like this problem is happening in the configuration subsystem.

What’s the best way to show all this to the developers and get their assessment?

2023-05-19 07:26:48.111 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-05-19 07:26:48.175 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:26:48.176 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
==> /var/log/openhab/events.log <==
2023-05-19 07:26:48.166 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:3070fe8bd9' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to INITIALIZING
2023-05-19 07:26:48.182 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:3070fe8bd9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
==> /var/log/openhab/openhab.log <==
2023-05-19 07:27:30.980 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:27:45.622 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:27:45.640 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2023-05-19 07:27:45.658 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2023-05-19 07:27:45.661 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to F7 22 FE A4 A9 8A 80 7C 65 FD 17 D6 47 1D C1 47 (String)
2023-05-19 07:27:45.663 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2023-05-19 07:27:45.665 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sisnode to 1 (BigDecimal)
2023-05-19 07:27:45.667 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_maxawakeperiod to 10 (BigDecimal)
2023-05-19 07:27:45.669 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2023-05-19 07:27:45.672 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2023-05-19 07:27:45.674 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2023-05-19 07:27:45.676 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/zwav
2023-05-19 07:27:45.678 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2023-05-19 07:27:45.680 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2023-05-19 07:27:45.682 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2023-05-19 07:27:45.684 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2023-05-19 07:27:45.686 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2023-05-19 07:27:45.754 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2023-05-19 07:27:45.757 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose
2023-05-19 07:27:45.759 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection
2023-05-19 07:27:45.760 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed
2023-05-19 07:27:45.762 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2023-05-19 07:27:45.766 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:27:45.767 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
2023-05-19 07:27:45.989 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:01.022 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:01.041 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2023-05-19 07:28:01.062 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2023-05-19 07:28:01.065 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to F7 22 FE A4 A9 8A 80 7C 65 FD 17 D6 47 1D C1 47 (String)
2023-05-19 07:28:01.067 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2023-05-19 07:28:01.070 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sisnode to 1 (BigDecimal)
2023-05-19 07:28:01.072 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_maxawakeperiod to 10 (BigDecimal)
2023-05-19 07:28:01.075 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2023-05-19 07:28:01.077 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2023-05-19 07:28:01.080 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2023-05-19 07:28:01.082 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/zwave
2023-05-19 07:28:01.085 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2023-05-19 07:28:01.087 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2023-05-19 07:28:01.090 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2023-05-19 07:28:01.092 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2023-05-19 07:28:01.095 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2023-05-19 07:28:01.151 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2023-05-19 07:28:01.153 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose
2023-05-19 07:28:01.156 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection
2023-05-19 07:28:01.157 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed
2023-05-19 07:28:01.159 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2023-05-19 07:28:01.160 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:28:01.162 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
2023-05-19 07:28:01.320 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:32.312 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:32.328 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2023-05-19 07:28:32.345 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2023-05-19 07:28:32.347 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to F7 22 FE A4 A9 8A 80 7C 65 FD 17 D6 47 1D C1 47 (String)
2023-05-19 07:28:32.349 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2023-05-19 07:28:32.351 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sisnode to 1 (BigDecimal)
2023-05-19 07:28:32.352 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_maxawakeperiod to 10 (BigDecimal)
2023-05-19 07:28:32.354 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2023-05-19 07:28:32.356 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2023-05-19 07:28:32.358 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2023-05-19 07:28:32.360 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/ttyAC
2023-05-19 07:28:32.362 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2023-05-19 07:28:32.363 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2023-05-19 07:28:32.365 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2023-05-19 07:28:32.367 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2023-05-19 07:28:32.369 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2023-05-19 07:28:32.431 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2023-05-19 07:28:32.433 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose
2023-05-19 07:28:32.436 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection
2023-05-19 07:28:32.437 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed
2023-05-19 07:28:32.438 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2023-05-19 07:28:32.440 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:28:32.442 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
2023-05-19 07:28:32.564 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:44.336 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:28:44.360 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2023-05-19 07:28:44.386 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2023-05-19 07:28:44.389 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to F7 22 FE A4 A9 8A 80 7C 65 FD 17 D6 47 1D C1 47 (String)
2023-05-19 07:28:44.391 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2023-05-19 07:28:44.393 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sisnode to 1 (BigDecimal)
2023-05-19 07:28:44.394 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_maxawakeperiod to 10 (BigDecimal)
2023-05-19 07:28:44.396 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2023-05-19 07:28:44.398 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2023-05-19 07:28:44.400 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2023-05-19 07:28:44.402 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/zwave
2023-05-19 07:28:44.403 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2023-05-19 07:28:44.405 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2023-05-19 07:28:44.407 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2023-05-19 07:28:44.409 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2023-05-19 07:28:44.411 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2023-05-19 07:28:44.473 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2023-05-19 07:28:44.475 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose
2023-05-19 07:28:44.476 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection
2023-05-19 07:28:44.478 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed
2023-05-19 07:28:44.480 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2023-05-19 07:28:44.482 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:28:44.484 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
2023-05-19 07:28:44.640 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:29:03.324 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:29:03.346 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2023-05-19 07:29:03.369 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_softreset to false (Boolean)
2023-05-19 07:29:03.371 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_networkkey to F7 22 FE A4 A9 8A 80 7C 65 FD 17 D6 47 1D C1 47 (String)
2023-05-19 07:29:03.374 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored security_inclusionmode to 0 (BigDecimal)
2023-05-19 07:29:03.377 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sisnode to 1 (BigDecimal)
2023-05-19 07:29:03.379 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_maxawakeperiod to 10 (BigDecimal)
2023-05-19 07:29:03.382 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_sync to false (Boolean)
2023-05-19 07:29:03.384 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_master to true (Boolean)
2023-05-19 07:29:03.387 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored inclusion_mode to 2 (BigDecimal)
2023-05-19 07:29:03.389 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update port to /dev/ttyACM0
2023-05-19 07:29:03.390 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_wakeupperiod to 3600 (BigDecimal)
2023-05-19 07:29:03.391 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_exclude to false (Boolean)
2023-05-19 07:29:03.393 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored heal_time to 2 (BigDecimal)
2023-05-19 07:29:03.394 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_inclusiontimeout to 30 (BigDecimal)
2023-05-19 07:29:03.395 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update ignored controller_hardreset to false (Boolean)
2023-05-19 07:29:03.450 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing receive thread
2023-05-19 07:29:03.451 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Receive thread dispose
2023-05-19 07:29:03.453 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Disposing serial connection
2023-05-19 07:29:03.454 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial connection disposed
2023-05-19 07:29:03.456 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2023-05-19 07:29:03.457 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-05-19 07:29:03.459 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:3070fe8bd9.
2023-05-19 07:29:03.580 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:3070fe8bd9
2023-05-19 07:29:08.475 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2023-05-19 07:29:08.506 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2023-05-19 07:29:08.515 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2023-05-19 07:29:08.517 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2023-05-19 07:29:08.520 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2023-05-19 07:29:08.566 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller

If it’s a standard openHABian that means zram is enabled which puts the $OH_USERDATA folder into RAM. It’s only written to disk on a graceful shutdown of the zram daemon (or a system reboot). So it might be possible you’ve set up all these configs, pull the power and all your changes are gone.

It might be possible to implement the USBIP client inside the container to avoid that problem. I’ve never tried it but it would solve this particular problem. But this feels like an XY Problem and chasing a solution to the wrong problem.

The last time I saw this looked at, WSL didn’t support hardware passthrough and neither did Docker for Windows. Has this changed?

Yanking the power even without zram on these machines is a bad idea. If the device happens to be actively writing to flash memory at the time power is lost you lose not only that one file, but any file that shares that sector. With wear leveling, that can be anything, parts of the kernel, file system tables, config files unrelated to OH, etc. You can end up with a corrupted system as a result.

Even with SDDs and HDDs, yanking the power without a graceful shutdown is a bad idea. So indeed, something to gracefully shutdown the machine is a must.

From what I understand, perhaps it is related to ZRAM. If what ZRAM wrote to disk is somehow off or has been corrupted from the lose of power, you are basically restoring that corruption to the ZRAM disk when you restart and any changes you made are being lost because you are yanking the power instead of gracefully shutting down.

I suspect corruption over stale state because, to my knowledge, the binding doesn’t really store any ephemeral state on disk. It’s all on RAM. But there are files it loads at startup from disk and if those are corrupted, recreating the Things would fix the problem.

I don’t think your problem is specific to Zwave. It’s a file system problem. It’s just the luck of the draw that you are seeing the problem on Zwave.

tl;dr: you can’t just yank the power from the RPi. If that’s a requirement for you, you need to find some other platform to host OH on. Hard resets are simply not supported on a machine running on flash memory and especially not supported on a machine running zram as you’ll lose everything.

You can’t get there from here. You’ll either need to figure out how to get the machine to safely shutdown or you’ll have to use a different platform.

Rich,

Understand your perspective but it’s impossible to guarantee a machine never hard resets. Whether it’s a power glitch or software hang, these things happen. You can make it rare - and I’m taking those steps. But sooner or later it happens. I’m tech support and really hate the support calls when something stops working. My experience with RPi is they are pretty robust on recovery and even on the SD card file system I can’t remember any of my Pis bricking from a hard reset.

If you look at the last log files I posted it appears that something strange may be happening with configuration, but it hasn’t affected any of the general site or user configuration information.

WSL does not support hardware pass through, which is what put me on the USBIP track in the first place. My testing did not give me much confidence in USBIP for production. Seemed great for dev and test where a human will notice and intervene when a connection hangs. Microsoft does not recommend WSL as a production platform and I concur. It’s not meant as a server. One of my to-dos is to switch from WSL to something different for production. I’m rapidly ruling out the Pi. The NUC looks good. I still have to evaluate native Linux / Docker vs Windows Docker running Linux containers.

I’m not 100% following what you’re saying about zram. Would I be better off mounting a USB drive and shutting off zram?

Just to back up, all I’m trying to do with the Pi is put the Zwave stick close to the controlled devices so I don’t have a distance or line-of-sight dependency between the main OH server and the thermostats. I’m open to any robust solution that recovers from power resets reliably. I initially thought a Zwave hub might work. Does OH have a binding to support Honeywell ZWave thermostats over a hub?

Agreed but the way flash storage works, you are playing the odds as to whether or not you end up with a corrupted file system every time you yank the power. It’s just how the technology works and you can’t get around that.

I’ve had it happen multiple times. YMMV but it’s a well known and documented limitation of the technology.

The way zram works on openHABian is:

  1. at boot the files on the physical disk are loaded into the ram disk
  2. during running all changes to the files occur only in the ram disk
  3. at proper shutdown, the current state of the files are written back to the physical disk

If you skip 3 by yanking the plug, you lose everything that happened in step 2. If there is something wrong with the files stored in step 1, you’ll get that bad stuff reloaded in step 2 even if you “fixed” it last time you booted. You lost the fix.

Note, this ZRAM configuration is actually a mitigation against file corruptions caused by loss of power. Those corruptions only occur if the RPi happens to be actively writing to disk when power is lost. Because the vast majority of writes in the openHABian ZRAM configuration occur to RAM, the chances the machine is actively writing to SD card is lower than it would be otherwise. It also mitigates SD card wear out.

The main point though is if you are not rebooting normally and yanking the power, you lose everything you did to the OH config since the last boot. So yes, if yanking the power is going to be part of your standard operating procedure instead of something that happens very rarely you need to turn off zram and switch to running off of an HDD (not USB thumb drive, maybe SSD if it has power loss protections which most do).

I’m using a USB RJ45 adapter to connect my 3D printer to my desktop. They work quite well. That could give you up to 150’ to work with if you can run a cable (theoretically).

Once you are dealing with a hub, openHAB doesn’t know or care if it’s Zwave. If OH supports the hub, it supports anything that hub can connect to.

Thanks for the explanation. The part that still confuses me is I’m not changing anything in the OH config. But if I’m reading the logs correctly (and from a quick look at the binding java code) it looks like OH may not be finding the string name of the Zwave serial port on a hard reset. That seems to be the root cause here, not broader FS corruption.

I agree with everything you’re saying but in 100 hard resets on my testbed my Pi has come up every time while the ZWave binding recovers 60% of the time. If it was up to me I’d suggest a developer to at least take a look at what’s going on. I looked at the java code and concluded it will take me at least a few weeks to get up to speed and build an environment to do anything with it and the problem is manifesting somewhere in the binding initialization sequence.

I’m not advocating hard reset as a daily procedure, but if it’s the sort of thing that happens once a year then I have to document and/or reverse engineer a fix under some duress. If I was a commercial integrator (which I’m not) I’d treat this behavior as a show-stopper. I went down the Zwave track rather than WiFi so I could control everything locally and not have a remote connectivity dependency.

I guess the next step is to explore moving most of the FS off the SD card. Perhaps leaving the boot image behind on a read-only card. All this complexity - UPS, external FS - is slightly undermining the Pi value proposition.

You’ve probably figured out I’m trying to wrapper OH so “regular” users will get the behavior they expect or a diagnostic I can interpret that helps me get the system running again quickly.

I would guess that you’re pulling the power when nothing is being written to the SD card, in which case you’re not simulating the actual worst-case scenario that you want to avoid. Try moving some files around and then pulling the cable while the writes are in progress.

You can. You can file an issue on GitHub. That’s how you get the developer to take a look. How to file an Issue

But, given no one else is reporting these same issues there has to be something unique about your particular setup that is either causing the problem or causing the problem to surface. It’s pretty hard to fix something that cannot be reproduced and the first set of suspects is going to be something related to the OS or a defect in the USB controller. The fact that is only occurs after pulling the power points to the OS.

As for the rest, openHAB is not and does not present itself as a commercial product. A Raspberry Pi (or other Single Board Computer) is not the only way to deploy openHAB and openHABian is not either. Be careful not to project too many requirements upon a system that was never intended to meet them. openHAB running on a RPi using openHABian, like any engineering problem, is an exercise in compromise between capability/reliability and ease of deployment. If those compromises don’t meet your needs, you have the option to choose a different approach.

I’d suggest opening an issue on the zwave github with your debug logs. There is only one developer for both zwave and zigbee.

Perhaps I do not understand hardware pass through, but I use OH on WSL when I want to test zwave code. I attach a zstick with
>usbipd wsl attach --busid 1-1

where busid 1-1 is the zstick identified with (in command prompt)

C:\Users\Robert>usbipd wsl list
BUSID  VID:PID    DEVICE                                                        STATE
1-1    0658:0200  UZB (COM12)                                                   Not attached
1-2    093a:2510  USB Input Device                                              Not attached
1-3    1c4f:0016  USB Input Device                                              Not attached
1-11   0658:0200  UZB (COM3)                                                    Not attached

1-11 is my zniffer

Thanks will open the issue.

Your usbipd command is connecting the usb device over IP (hence USBIP). You are typing a command to the server end on Windows (usbipd) that forwards a command to linux to initiate a USBIP connection. I am running the NUC on Win10 and had to rebuild the kernel to support usbip, but apparently it’s native in the Win11 version.

I found it was great for development, but if I left it running for a couple days the connection would fail or lose sync. My second try was to remote the usbipd to a Pi, but had the same issue with the client side. That’s how I got on this whole track of using the OH remote binding to communicate to the zstick.