Having been running 4.0.0.M2 for some time, this evening (after a random Java crash) I decided I should update to the latest Milestone, and it has… gone pretty badly, TBH.
The major problem was the new need (which I gather was introduced in M3) to add units to every item metadata separately to the units already specified in the state description. While I kinda get that one should be able to do that, the requirement to do so seems like a bad one - the previous behaviour of “if it’s not specified in the metadata, use the state description”. It certainly broke a lot of things in a lot of unexpected ways, and once I finally dig myself out I’ll need to wipe a few hours of garbage from my influx database. I’m still not really sure how close I am to digging myself out of the new unit specification requirement, because unfortunately the log has stopped reporting things it used to report all the time, and I can’t really tell if that’s because significant elements of the system aren’t running, or because it’s just decided to stop logging them.
Weirdly, the first time I ran it (before fixing the item units), the log behaved as I was used to it behaving before… which was how I first noticed the problem, seeing rain rate and wind speed both reported in km/h rather than mm/h and kn respectively. Now that I’ve stopped it, fixed all the unit metadata, and started it again… no item state changes are appearing in the log. I think they’re still being updated - at least, looking at grafana they still seem to be being persisted - but I can’t see anything about it happening.
I’ve checked log:get, and although it shows openhab.event.ItemStateChangedEvent as INFO level (after I manually added it - it wasn’t listed at all previously, but openhab.event was always there and showing INFO as well)… well, there’s just none of them showing up in the log.
Probably what I’ll do is strip all the previously-unnecessary metadata out of the items files, shut it down, and downgrade to M2 again. M4 seems unhealthy, and I need the system to run. If anyone has thoughts as to why the new item metadata should have broken the logging of item events.
Further test data: reverting the item files only and restarting openHAB M4 didn’t fix the logging problem. Deleting the entire window of data (the whole evening, unfortunately - might have been able to be more targeted, but I didn’t know what persisted data was messing it up) from influx and downgrading to M2 has it back to working perfectly… so I think I’m going to give M3+ a wide berth for now. The item unit metadata change seems messy and possibly not yet fully functional.
I might do further testing over the next few days, maybe trying to jump both item files and the OH version back to the target state, but only for active testing over a short period to see how the units/items behave, in order to minimise the amount of data I need to wipe to get it back to functional if the unit handling continues to bug.
How did you upgrade because if you had units in your State Description pattern, the new upgrade tool should have added unit metadata for those Items as part of the upgrade process if they were managed Items. If you upgraded in a way that somehow bypassed the upgrade tool that would skip this step. Or if you are using .items files the M3 announcement (and the OH 4 release announcement) has instructions for what you need to do prior to upgrading.
As for whether the requirement was a bad one or not, there was a huge discussion on how to proceed with making OH’s handling and processing of UoM sane by removing ambiguities. For example, let’s say one had a Channel that updates an Item with °C. But they live in the US so they want to see the value in °F. With the State Description approach the Item’s state is °C and it’s shown as °F in MainUI. However, °C is saved to the database but data saved to persistence is not saved with their units. So when OH goes to restoreOnStartup it’s going to load that original value from °C but apply °F as the unit because that’s the only unit OH knows at that point and the state will be wrong.
To solve that and similar problems, there had to be a separation from display and the Items state, hence the new unit metadata.
The announcement for OH M3 was clear that this change is a breaking change and what to do about it.
There is nothing having to do with the way units are handled that would impact logging. I suspect this is a different and unrelated issue. do you notice any other related patterns in which Items are being logged and not? Is it just events.log that is impacted? Are you seeing any events on these Items or are you missing just some of them (e.g. you say you are not seeing ItemStateChangedEvent but are you seeing Commands and ItemStatePredictedEvents)? Do you notice anything that may be off in your log4j2.xml config? Here’s a link to the default file: openhab-distro/launch/app/runtime/log4j2.xml at ca7e75ab4db186ee73dc982af30d3aea2e24fca3 · openhab/openhab-distro · GitHub. Maybe during the upgrade a typo of syntax error occurred?
As expected. There is nothing to do with the UoM changes that touches logging. Something else is going on.
It was probably the downgrade that “fixed” it in this case.
Honestly, it’s only messy if you don’t follow the upgrade instructions. If you have managed Items, the upgrade tool should handle everything for you. However, if you have .items you’ll have to add the unit manually. The upgrade tool will not make changes to your text fine based configs.
Please do read the M3 announcement and follow those instructions first before attempting any upgrade.
It is fixed in M4. @JustinG provided an example widget in the linked issue and I verified my fix against it. Can you please reload MainUI from the „Help & About“ page? If it still does not work, please open a new community thread and share your widget code.
Thank you for the detailed reply - I’ll get stuck into detailed work on this situation later on. The upgrade process was done the same way as I’d done every other upgrade since OH3.0, at the command line.
sudo runtime/bin/update 4.0.0.M4
Looking back through the warnings that are given using that command, and comparing to those that appear when I use the corresponding command to downgrade to M2, I can see that the line regarding UoM refactoring has been added to the middle (?!) of an otherwise apparently unchanged set of warnings from the earlier v4 milestones… but since the link given in that warning says nothing at all about using a different upgrade technique or what manual changes would be needed (you can see for yourself - Installation Overview | openHAB), I’ll give myself a pass on having not seen those instructions until I saw the odd behaviour in the persisted data.
Is it possible for the upgrade script to display those things which are new to the version target of the upgrade (or new between the existing version and the upgrade version)? That would make it way more useful than having to play “spot the difference” on the release warnings.
However, I don’t think it would have made much difference - I use all text config files for my items, and what I did after discovering the unexpected behaviour in M4 was to come and read posts in this thread which mentioned UoM issues in M3+, find the link about the UoM change, and manually go through and update my item files. That may or may not have been successful, but I can’t tell because of the logging issue that appeared when I next started OH after updating all the item files (and which then persisted through restarts of OH, and even restarts of the whole system). I know you say it doesn’t have anything to do with logging - and I believe you, but that’s was the point at which the logging broke and I couldn’t get it working again until I reverted the item files and downgraded to M2 (which fixed it instantly). The curious thing is that the sequence of events doesn’t give any reasonable explanation of the logging problem:
upgrade from M2 to M4 and launch it
while monitoring log entries (as I normally do - I just leave “log:tail” running in the terminal window), notice the UoM problem
look up this thread, find the instructions to update item files
stop OH
update all item files according to instructions (this was the only change)
start OH
item change events no longer appear in the log:tail, despite my being able to change item states through my OH sitemap interface (can see the lights turn on and off, but nothing appears in the log)
That makes sense - and I understand it’s a major headache to get things working in a consistent way behind-the-scenes to what the user sees. I suppose what I’m thinking isn’t so much a change in the logic that has been decided upon - I gather that makes sense, for all that I’d got everything working very nicely prior to the change. However I’d suggest that it might make sense to interpret .items files differently so that they are more likely to behave as expected from one version to the next. My suggestion would be to handle units on items as follows:
Item displays in mm and persisted in mm. The system infers that if no unit is specified in the metadata, it should be the same as what is used for display. Thus it behaves identically to the following:
At present, my understanding of M3+ is that if the unit isn’t specified in the metadata, then it now reverts to the system default units, which I believe is only the appropriate behaviour if units are also not specified in the state description.
re-copied all the .items files that I’d previously edited to include unit metadata into the conf/items folder
started OH
… and it’s working! log:tail is showing everything it used to.
But wait …
stopped OH
started OH
… and it’s not showing any item updates in the log any more. I literally did nothing except stop OH and start it again. Behind the scenes I believe it’s still working, but the log not showing anything is not acceptable. At least now I have confirmed it’s nothing to do with the items files being changed, because I changed nothing between the first run and the second. My problem is that the first run after upgrading to M4 works, and the second and subsequent runs, the logging - while still operating for certain things, is failing to log anything relating to items updates.
I’ve had a look for that log4j2.xml file you mentioned - in my OH installation, it appears to be in userdata/etc… and it appears that Karaf itself added some entries at the end of the file, including what appeared to be a blanket nothing rule for item updates. The file I had was quite different in a number of respects to the version you gave a link to, so I replaced it with that linked file… and the log continues not to show item state changes. It’s a rather annoying bug, but at least the rest of OH seems to be running properly for now, so I’ll leave it running M4.
Further update: I’m obviously reporting on things as I test them, but I think in fact there’s something more fundamentally wrong with M4, at least as far as what it’s doing with my installation. I have a number of values in my system that are persisted, and I can see that there is a subset (which are calculated by rules rather than fed in directly from bindings) which are no longer being updated since the first stop-and-start which killed item change logging. So it is as if the system is in fact failing to recognise that items are changing at all - it persists the changed value, and when I look at the value in the sitemap it is correct, but anything triggered by a value changing fails to be triggered - including both rules and logging. That is of course a much, much bigger problem, so I think it’s time to roll everything back to the working M2 installation.
You of course are free to create a PR to request that change, but that approach was rejected during discussions. I don’t remember the specifics but I think it had to do with technical limitations and not wanting two different implementations in core. Also, ultimately what you describe is largely how it works now so your suggestion would ultimately mean “let’s leave this problem mostly unfixed for text file based users.”
The behavior is as follows.
Managed Items:
The upgrade tool finds all the managed Number:X Items and for each one creates unit metadata as follows.
Uses the unit from the State Description Pattern
If the unit is %unit% or there is no State Description Pattern, use the unit the Channel publishes
If 1 and 2 don’t exist use the system default.
The unit can be overridden at any time by the end user.
Text based Items:
The unit metadata must be added manually, either in the file or through the REST API/MainUI (metadata can be managed while Items are in text files, though I don’t recommend it).
At runtime, if the unit doesn’t exist the unit used follows this hierarchy.
The unit published in the state update.
The system default.
It mainly works differently from managed in that the upgrade tool makes sure the Items have unit metadata while for text file based users it’s up to you to make that happen.
Did you issue any other log: commands from the Karaf console? If, for example, you issued a command to change the logging level of a given logger name, that actually adds lines to that log4j2.xml files. That’s really the only way I know of that that file will change outside of manually editing the file yourself (or changing the logging level of a binding through the UI or REST API but I think we can exclude that case here).
It might help if you describe exactly how you’ve installed this and on what operating system.
You can verify that the events are occurring through the developer sidebar. You can see the raw unfiltered event stream there (and of course you can filter if as needed). That will confirm whether or not the events are happening.
But it might be time to move this to another thread to further research. No one else has reported anything like this yet so it’s going to take some research and experimentation to figure out what’s going on.
I’ve now done that, and it seems to have worked. As a once-off thing that should be future-resistant, it was somewhat annoying but now it’s done. I trust that the reasons for the logic of items files was sound, definitely not worth a PR to re-open that can of worms.
Actually I think the issue is not fundamentally a logging issue - I did try using log:set to explicitly set the log level for item state changes, but I’m pretty sure we need to look elsewhere.
I didn’t know about that - I shall fire that up and see what I can discover. And I agree - it sounds like this now belongs in its own thread. Time to upgrade to M4 again and continue testing.
All of the issues that I identified in moving from M3 to M4 have been corrected in latest SNAPSHOT build. Kudos to the development team for the ability to quickly respond, identify the root cause and implement a fix. Very Impressive!
Other than that seems ok. Will test further later on.
Have a lot of these errors now but that is probably because I changes the json file:
2023-07-08 10:21:09.105 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript;version=ECMAScript-5.1' could not be found for identifier: 107fce72-0845-4f8f-a377-61a9e72fe5a4
2023-07-08 10:21:40.528 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript;version=ECMAScript-5.1' could not be found for identifier: 2fc3dedc-efa6-484b-a046-e33dc89b0717
2023-07-08 10:21:40.650 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript;version=ECMAScript-5.1' could not be found for identifier: 107fce72-0845-4f8f-a377-61a9e72fe5a4
I also noticed another thing, which didn’t happened in 4M2 - although I’m not sure whether it is Openhab issue or something with Influxdb itself.
In any case, since M4, storing of state change state takes bit longer than it used to and in one rule I had to increase delay for correct reading of persistence from 500ms to 3500ms. I admit, I have bunch of items, some of them are stored on change but such problem did not exist in M2.
Additionally, I get following errors with RRD4J now, which sort of suggest, that items are also not persisted in order any more too. I’m using default RRD4J persistence settings
2023-07-07 10:48:00.622 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688719680, last update=1688719681. Discarding LogViewer_ManualUpdate - 0.0
2023-07-07 10:20:00.542 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688718000, last update=1688718001. Discarding PowerPlug_07_Power - 1792.0
2023-07-07 10:07:32.802 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688717252, last update=1688717253. Discarding MotionSensor_09_LinkQuality - 105.0
2023-07-07 10:07:32.777 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688717252, last update=1688717253. Discarding MotionSensor_09_LinkQuality - 98.0
2023-07-07 09:59:23.096 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688716763, last update=1688716764. Discarding PowerPlug_09_Quality - 91.0
2023-07-07 09:37:39.472 [WARN ] [d4j.internal.RRD4jPersistenceService] - RRD4J does not support adding past value this=1688715459, last update=1688715460. Discarding PowerPlug_09_Quality - 83.0
I’m seeing @reyhard’s messages too.
I have opened Persistence warnings · Issue #3697 · openhab/openhab-core · GitHub.
Various items, nothing special about them. Maybe except that all of them are UoM items and have unit metadata set.
But I think the key is the warning only appears when they’re updated (or rather persisted as specified on every change) multiple times in a second.
