Openhabian + RPi4 + Zwave Gen5 falls offline on restart

Thanks for the ideas.

If I’m reading the SD card mirroring documentation correctly, I still need to manually swap cards if there’s a media failure. My Pi is on a UPS but would still prefer a solution that can recover unattended from power glitches.

I wonder if mounting an external SSD drive on a USB/SATA adapter and USB booting would work? Haven’t looked if Raspbian supports USB boot. How to Boot Raspberry Pi 4 / 400 From an SSD or Flash Drive | Tom's Hardware. Unless the issue is the zwave binding leaves state it can’t deal with on restart in the file system when the binding is not shut down gracefully.

Thanks for the heads up about gen7.

It works, and there’s been discussion of it in the community. Note, however, that SSD is not supported by openHABian. That just means the maintainers can’t/won’t help troubleshoot a system with an SSD, because it introduces so many variables.

I feel like something is wrong with either your hardware or your installation, and would suggest that you try a fresh install to see if it still happens. And if you have an RPi3, I would suggest testing with that as well. It would be more than fine if you’re just using is as a remote OH server for Z-Wave.

I started messing around with DietPi this weekend and the VirtualHere software caught my attention.

VirtualHere allows USB devices to be used remotely over a network just as if they were locally connected!

There’s a command line client for Linux, so this would theoretically work for a Z-Wave stick. It could be a perfect use case.

The RPI is a clean install of openhabian with only the one Zwave binding installed. Lot of threads on OH and HA groups about USB hardware compatibility issues between Zwave Gen5 and RPi4. Consensus is an external USB hub solves the issue. I’m using a Moxa 404 powered USB2.0 hub I have lying around. Seems to be no clear consensus in the RPi community that USB boot to a SATA drive is better than micro SD with zram.

The ZWave connection appears solid once it comes up. The problem is cold booting after a non-graceful shutdown. Pure speculation but stale file system lock? Timing issue on boot sequence? I don’t even know where to start looking.

After the couple days I spent testing USBIP I’m hesitant to try another remote USB approach. My main instance of OH is running under Docker (currently under WSL2 on a NUC) so I have to create the remote device before I start Docker and inject a port into a container. Docker gets really unhappy if you try to map a device that doesn’t exist.

I had to rebuild the WSL linux kernel to run under Win10 WSL. It works, but not supportable and not stable IMO so I reverted to a released kernel and added the Remote OH binding.

I’m testing a port to HyperV. The reason I want to run on the NUC with Windows is my BACNet PLCs have a config app that is native Windows, and I’d like everything with climate automation on one server if possible. Also OH with Docker is fabulous! I can bring up a test version in just a few seconds without affecting production at all.

I don’t have this stick, but I recall that it was less about the external power and more about forcing it to be recognized as a USB2.0 device. So maybe try removing the power from the hub.

Does your USB not have a USB connection so that you can execute a graceful shutdown?

I’m seeing the same behavior with the stick directly on a Pi port or on the USB hub. FWIW my Moxa hub is USB2.0 which should force the right behavior in the stick.

The Pi is hanging on a DIN rail and not close to any screens. I guess I could add a switch to the Pi to command a graceful shutdown for service, but I’m getting dangerously close to thinking Zwave isn’t worth the trouble.

Not that it’s any surprise, but stable communication with physical devices seems to be a struggle. I started with a bank of legacy thermostats talking RS232/ASCII commands. I wrote a Python parser using the MQTT binding. Stats couldn’t keep up with enough reading and writing to keep the OH states current. Then I tried BACNet with a small PLC. That works fine for my radiant zones, but I couldn’t get the BACNet PLC with the 3rd party BACNet binding to route commands to and from BACNet/MSTP on RS485. Now I’m trying ZWave. First try was a direct ZWave connection from the NUC, but under WSL I needed to use USBIP even locally. That worked for test but was very fragile and unstable. Tried remoting the USBIP to a Pi and still fragile. Now running a remote OH instance on the PI to manage the Zwave. It never occurred to me ZWave on a Pi running Debian (Raspbian, Openhabian) would be finicky.

Will see if I can narrow down the failure mode.

Add an off-switch to power down your Pi — The MagPi magazine (raspberrypi.com)

Just to be clear, what I’m suggesting is to use the Moxa hub without external power, or swapping in any old USB2.0 hub. What I’m wondering is if the problem is related to the stick continuing to have power. I’m grasping at straws with this, but just trying to work through hardware variables.

There’s no point to testing with the Gen5 stick plugged in directly, as that’s known to be a problem.

Have you tried it on an RPi3? I’m just curious if you’ll see the same behaviour.

I think what I’m missing is why the dirty shutdowns are happening. I assumed that you were trying to plan ahead for power failures, but you mentioned that you also have a UPS. If the UPS has a USB connection, you can use NUT to execute a graceful shutdown whenever the battery is nearly depleted. As you noted earlier, the only issue is that the RPi won’t turn itself back on afterward, but that’s only going to happen whenever you have hours-long outages.

It now sounds like you’re intentionally unplugging the RPi while it’s running and expecting it to be okay afterward. In which case, yes, add a switch to do a graceful shutdown.

The thing is, it shouldn’t be. I have a Zooz USB stick in an RPi4, and it gives me absolutely no trouble at all. Since you’re running a fresh OH, I’m inclined to think the problem is your Gen5.

New question: how far is your remote RPi from your server? If it’s in the same building, you could just put in Z-Wave plugs/switches to act as a repeaters. That has diminishing returns, but may be easier and more reliable in the long run.

Yes I’m yanking power on the Pi for maintenance and development. FWIW the only service that’s not recovering on reset is the z-wave binding.

I’m not being nice but generally I expect stuff like this to recover gracefully even if I slightly mistreat it. At first I thought the problem was with the stick or maybe the SD card, but now my best guess is the binding can’t recover from stale state when it restarts.

My UPS is a larger unit that protects critical circuits in the house. I don’t have any local USB notification available on UPS status.

Trying to work with legacy equipment and end up with automation that recovers without manual intervention. Lot of tired things about AMX, but it’s been very good at recovering from unscheduled resets.

Installing the stick in the main server and colocating with the z-wave devices is a possibility but creates hardware and software dependencies that are hard to maintain. But that would be a whole other thread to describe all the things I’ve tried and abandoned on this project.

I’m only skeptical of this since I haven’t heard of anyone else having the same issue. There are tons of people using those Gen5 sticks, so I feel like we’d have heard something if that were the case.

Excellent point. I’ll try a fresh install on another Pi4 and see if anything changes. I don’t have a Pi3.

I also wonder if there’s any way to tell if my z-wave stick is counterfeit?

lsusb reports:
Bus 001 Device 004: ID 0658:0200 Sigma Designs, Inc. Aeotec Z-Stick Gen5 (ZW090) - UZB

Fresh openhabian install on a different RPi4 with a brand new Aeotec Z-stick Gen 5+, no USB hub. Aeotec claims the Gen5+ is RPi4 compatible.

Added udev rule for a symlink and installed Z-wave binding. Serial Controller shows ONLINE.

On a soft reset (systemctl or reboot) the Z-wave binding recovers ONLINE.

On a hard reset (power cycle) the Z-wave binding stops working every few cycles and then won’t restart. I’d like to say I’ve found the formula to restart it but I can’t say whether it’s removing the bindings and reloading, hard reset followed by soft reset or random.

What I see in the logs is the “Starting Zwave Controller” message is missing when the binding remains OFFLINE and a “HANDLER MISSING ERROR / Handler Factory not found” from the thing log.

Any thoughts on what would keep the ZWave Controller from starting? The device and the symlink are present in /dev. Stick is showing a green light.

I’ve ordered an Alchemy UPS hat for the PI, but IRL I can’t guarantee the PI will never encounter a hard reset. This is easy to reproduce: just load Openhabian on a PI, plug in a ZWave stick, load the binding and try a series of hard resets.

============================
2023-05-18 07:25:01.085 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to ‘America/Los_Angeles’.

2023-05-18 07:25:01.172 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ‘36.85618392376164,-121.87500178813936’.

2023-05-18 07:25:01.175 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to ‘en_US’.

2023-05-18 07:25:27.853 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007

2023-05-18 07:25:35.132 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel

2023-05-18 07:25:37.352 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

2023-05-18 07:25:43.436 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null

2023-05-18 07:27:16.224 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Stopped HABPanel

2023-05-18 07:27:16.267 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI

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

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

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

2023-05-18 07:27:15.892 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:c17dc773cc’ changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to UNINITIALIZED

2023-05-18 07:27:15.913 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:c17dc773cc’ changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

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

2023-05-18 07:27:52.760 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to ‘America/Los_Angeles’.

2023-05-18 07:27:52.848 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ‘36.85618392376164,-121.87500178813936’.

2023-05-18 07:27:52.851 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to ‘en_US’.

2023-05-18 07:28:18.835 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007

2023-05-18 07:28:24.037 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

2023-05-18 07:28:25.720 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel

2023-05-18 07:28:33.044 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null

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

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

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

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

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

2023-05-18 07:28:38.213 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

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

2023-05-18 07:28:41.699 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘zwave:serial_zstick:c17dc773cc’ changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

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