The only way that this can happen is if something (ie openHAB core) is disposing of the handler. In the dispose method it closes the serial port and sets the serialPort field to null. We see that this is null in the logs and we see that dispose is being called.
2019-12-15 11:00:09.562 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
Why this is happening, I don’t know. The only thing I can think of is that at some point (prior to any of these logs) the binding was restarted (or more precisely, the handler was restarted). Maybe this hasn’t closed down properly and there is the remnants of a past handler still left.
The fact that you’re still receiving messages indicates that this is likely the case - if the serial port was really null, it would not receive, so my guess is that there are two copies of the serial handler running due to a thread being left open.
None of this code has changed for an awful long time so from a 2.5 perspective I don’t think it’s a regression.
Well, first log is from openHAB startup, so I suppose a binding restart would be seen in that log?
Is there any other log that I could enable to give more information?
I have no clue what to look for, but now I think that there’s some kind of watchdog restarting just about every bundle - I tried stop a couple of bundles related to serial, but they are restarted once a minute.
So then I stopped a lot of other bindings, and they are also restarted once a minute, just that they are more silent about it. Or is this intentional nowadays (this auto starting)
Maybe I better put this into 2.5.0.RC1 issues thread!?
I don’t know, but if you are saying that working bindings are restarting, then something strange is happening and I’d be surprised if that is a standard OH feature.
I think that thread is horrible as it’s a real mess of information, but up to you - I don’t follow it though. Also 2.5 is currently about to be released (I think the build has already started).
One point though - as far as I know, you are the only one with this issue?
I don’t see anything in the log that indicates why the handlers are closing, but they are. You see this for all devices a couple of minutes after startup - there’s no indication as to why this is happening that I can see. The binding never calls this dispose method - only the framework does.
How are you configuring your system? I wonder if there’s something strange with files being touched that causes the system to think that config files are being updated or something (might explain why bindings restart every minute).
Good Idea! But I can’t think of any problems with time/touched files etc. I looked at all files under conf, and could not find anything very recent.
Maybe I am alone with this, and if 2.5.0 is already on its way, it is anyway too late for a fix for that.
I think next step is to do a clean install. But that is getting too late for today, so I think I’ll go back to M4, and deal with this after Christmas.
Thanks for trying to help!
OK, after doing a lot of tests (thanks @chris for ruling things out, and getting me on the right path!), I now know what is the issue in my system. Between M4 and RC1, there must have been a change how OH treats binding startup failures: I had “http” in the bindings line in my services/addons.cfg that did not work. I guess it should be “http1” nowadays(?). Anyway, in M4, this just gave an error in the log file, but in RC1 (and M5 I guess), this makes OH reset/restart all(?)/most bindings once every minute, including Z-wave binding, which in my case is very large/easily spotted.
After removing “http” from my binding line, I have run without any issues. When I put it back, back comes the issues.
This might be useful to know, and maybe also this explains other peoples issues.
The feature installer runs every minute to look for bindings that need to be loaded. If there’s an invalid binding in addons.cfg (or possibly in userdata/config/org/openhab/addons.config), the feature installer will try to install it over and over every minute. As an aside, in this scenario there also happens to be a memory leak somewhere in the feature installer that will eventually cause openHAB to run out of memory.
Edit: This behavior has been there for a very long time (coming up on 2 years). I’ll reference the issue in a minute.
OK, good to know! But the change between M4 and RC1 is that other bindings (for sure zwave in my case) are reloaded/reset/?/, or parts of it. I only know that this exact thing is what made my zwave binding go bananas every minute. So it should not be directly related to the memory leak. (unless the leak is huuuge of course).
In order for it to occur, you need to have an invalid binding in addons.cfg. Is that true in your situation?
jwiseman
(Mr. Wiseman (OH 4.2 Snapshot on Pi4))
980
Timing issue on Zwave binding on startup?
I seem to have a timing issue on when the zWave and Serial are loaded during startup. Is there a way to change the order of a PID for the zWave binding?
When OH fully starts up; I have to stop and start the zWave binding to get it to put all the devices online.
Binding version:
209 │ Active │ 80 │ 2.5.0.201910162319 │ org.openhab.binding.zwave
Logs:
2019-12-13 08:43:52.628 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-12-13 08:43:52.761 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2019-12-13 08:55:28.518 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2019-12-13 08:56:04.747 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-12-13 08:56:04.873 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2019-12-13 08:56:04.977 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-12-13 08:56:05.062 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-12-13 08:56:05.062 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
Best, Jay
jwiseman
(Mr. Wiseman (OH 4.2 Snapshot on Pi4))
981
I’m not sure; these are the ONLY entries for the bindings below; the rest are dropped in addon’s.
2.4 with a 2.5 binding? Possibly.
The 2.5 binding was not designed to work with 2.4. It just happens to work. Amazingly, it was designed to work with the 2.5 version. There have been a multitude of changes between 2.4 and 2.5. That is why it is being released 6 months later than originally planned.
jwiseman
(Mr. Wiseman (OH 4.2 Snapshot on Pi4))
984
Been running in this conf (2.4 on 2.5 zWave binding) for close to a year now with many updates to the zWave 2.5 version. My issue is a one off based on many /cache & /tmp clear outs. Just wondering if it’s possible to change the PID order in general based on changing a cache file since it’s the same PID every time you startup OH?
This was the issue with my OH installation. It wasn’t addons.cfg, but addons.config file (in OpenHAB\userdata\config\org\openhab folder) that had plex and plex1 in bindings section (even though there’s only OH1 binding for Plex). After removing it and updating OH to the latest nightly, Z-Wave controller works as expected.
Thank you and @chris it was my issue as well, after upgrading to 2.5GA last night, Zwave and Powermax flapping. I went into addon.config and found action.pushbullet and misc.restdocs. probably old addons that was removed, however still appeared in my config (installed from paper, not manually)
EDIT: so, my fault, its registered under “Things to do before upgrade”
