openHAB 4.0.0.M4 problem with state changes

  • Platform information:
    • Hardware: Mac Mini intel core i7, 16Gb RAM
    • OS: MacOS 10.15.7
    • Java Runtime Environment: Zulu17.42+19-CA
    • openHAB version: 4.0.0.M4

Continuing the discussion from openHAB 4.0 Milestone discussion, I seem to have discovered a peculiar bug in M4. Specifically:

  • after upgrading from M2, the first time I start openHAB it appears to behave normally. It is my usual habit to monitor the running of openHAB with a log:tail command in the karaf console, which I just leave running in the terminal window in which openHAB itself is running. I have item change state events set to INFO log level, so I see every time an item changes state.
  • Also during this first run of openHAB, rules that are triggered by an item changing state operate normally - for example, I have a rule that calculates dewpoint from temperature and relative humidity (the latter two are reported by my weather station binding, but not dewpoint). This rule is triggered each time the inside temperature changes.

However, after stopping openHAB (which I just do by typing ^D at the console) and starting it again, item state changes no longer appear to do anything. Items still do change state if something changes them - the changed values appear in persistence data and in the Developer Sidebar - but the rule I mentioned above is never triggered, and not a single state changed event appears in log:tail. I have now downgraded to M2 and upgraded back to M4 several times, always with the same behaviour:

  • M2 - works perfectly across multiple stops and starts.
  • M4 - works correctly only during the first time it is run after upgrading, but as soon as openHAB is stopped and started, it ceases either logging of or triggering of rules by item state changes.

I will do further testing, including trying out M3 to see if the problem is introduced by a difference between M2 and M3 or between M3 and M4, and will report back. In the mean time, any suggestions as to what else I might try to track down the cause of this rather serious problem would be appreciated!

Update: M3 appears to continue to work after stopping and starting openHAB, so this appears to be a problem that has only been introduced between M3 and M4. I will leave M3 running for the time being.

During startup do you see anything odd or weird in openhab.log?

Note that during an upgrade/downgrade the cache gets cleared which causes OH to have to download and install all the add-ons again. This can take some time. In the mean time, OH continues the startup process and weird errors may occur when, for example, the rule engine starts but the automation add-on(s) are not yet available or only partially installed.

I’ve been in the habit of upgrading, waiting for long enough for OH to fully come up while watching openhab.log. If there is anything odd in the startup I’ll give it a couple more minutes and then simply restart OH.

This doesn’t seem to be a problem in the latest snapshots (there were some changes made to address this). It also doesn’t seem to be exactly what you are experiencing as it appears that the first boot of OH works but subsequent boots do not. But there might be something related.

Have you tried a third restart once the errors start appearing?

What happens with the latest snapshot?

There’s nothing weird when I’m viewing log:tail (and what I see in openhab.log appears to be a subset of that)… but what’s curious here is that the problematic behaviour is absent in the first run, but then commences the second time I start OH and persists through every stop/start thereafter, no matter how long I leave things running. I have indeed tried a third restart, and a fourth, and even a complete system reboot, to no avail.

And the problem only happens in M4. As soon as I downgrade to either M2 or M3, it starts up and works perfectly, and if I stop and start it again, there continues to be no problem.

I will test the latest snapshot and report back.

OK - just tested upgrading to latest snapshot build, and that works perfectly through at least three starts. I guess whatever weirdness was going on for me specifically in M4 has been resolved in the changes between M4 and snapshot build #3530, so as long as the relevant change isn’t reverted, we’re in the clear!

This is a live system in use, so I’d always taken the “use snapshots at your own risk” as a basis for avoiding them, but I suppose while this continues to run well I may as well leave it until the next milestone build.

At this point the snapshots are mainly bug fixes with just a few new features being worked on. There won’t be another milestone for 4.0. Next week there will be a code freeze and a couple release candidates and finally 4.0 release before the end of the month.

There have been a number of bugs fixed since m4, hopefully this was one of them.