Proposal to Reduce default LogLevel of ItemStateChangedEvent in events.log

[blilleike]

In short, I have learned, that ItemStateChangedEvent is triggered as a default Info-Event by Core to track all events. I would propose to disable the logging of this type of Event by default.

Some Bindings like Squeezebox and event Z-Wave serial stick trigger a lot of those events by design. My brand new openHAB (< 2 days) has 3MB events.log, on the previous system I had collected 124MB in 2 Month. A smarthome is (can be) running for quite some time unattended after the intial setup is done.

My concern is, that the current default will break installations of users with only the typical 16GB card and listening e.g. to a lot of music. I had to debug a zway install after it ran some years to find out, that the log just grew uncontrolled.

Even if the grow might not be a concern because the max size is somewhere managed and limited, I would argue that a permanent logging of those events is in most cases unneeded. To debug it can be turned on and then turned off again for production. Or left on if really wanted.

Even to help a new user with an issue might be easier, if the first debug step is to turn on the log, then reproduce the issue and then send only this small log to whoever volunteers to help decode it. In my opinion it is psychologically better to have this learning of turning it on and see the new file with exactly what happened since turning it on then be overwhelmed with potentially 100 of MB of loggings.

This has been (misleadingly) been discussed in a bindings-issue and now moved over here. https://github.com/openhab/openhab2-addons/issues/6022

[blilleike]

rkoshak argued: You might get somewhere by pursuing turning off events.log in the first place though. The entire log file, not just piece parts.

I would disagree. The events.log also has entries of ExtensionEvent (install/uninstall of components), ThingUpdatedEvent, ItemChannelLinkAddedEvent, ThingStatusInfoChangedEvent (and probably more)

Those are only triggered by configuration changes and should be quite useful for debugging and can not be reproduced after changing the loglevel in case of a problem.

[rkoshak]

Then my position is that ItemChangeEvent should remain being logged at the info level.

The value of knowing when an Item changes state is at the same level as knowing when an Item receives a command. So if you move ItemChangedEvent to DEBUG then you should move ItemCommandEvent (or what ever it's called) too.

At that point you will have moved all of the Item events to the debug level (Update events are already at the debug level).

Since the majority of users who do look at events.log do so primarily to see Item events, changing either to DEBUG level would be an unacceptable degradation in the utility of events.log.

To bring in your arguments from the forum thread, your stated primary motivation for this change is to address concerns that casual users of OH should not need to make changes to the logging config in order to stop Item Change events from spamming the events.log. How many of these users will care about any of these events?

You argue that seeing these Thing related configuration events is useful for debugging. In my experience these entries have never been useful for debugging because the only time they will appear in events.log is if the activity successfully occurred which will also be apparent in PaperUI. If something went wrong, these events would not be logged and there will be actual errors which are useful printed to openhab.log.

On the other hand, seeing the Item events, changes and commands, can be hugely useful for developing and debugging your self developed Rules. Even casual users of OH may find those entries useful. "Why didn't my Rule run? Oh, according to events.log the Item didn't change state..."

So I maintain that either events.log should remain as is and for those users who use the rare binding that "spams" the event bus with change events can, if they choose, follow the many tutorials to turn logging off for that one or two Items, or events.log should be turned off by default.

[Hilbrand]

Thanks for put the issue here. As is mostly the case something that looks simple isn't.

The event.log is (as @rkoshak also mentions) a useful feature, because it has data that can not be seen in another way. For example Home Assistant stores all events in a database and has the ability to show a timebased graph of these events per item. (Although it causes massive databases that need to managed in order to not run out of diskspace). Therefor I would argue that the event log should be seen as useful tool, albeit maybe not the best interface. And simply hiding these logs would remove users of that valuable information. That is. More users need to take action to enable it than users that now will disable it because the logs are to verbose. So unless this feature is provided in another way the logging is useful.

Doesn't it mean it isn't an issue? No. I think it's something to think about. This is a specific issue for what I would call streaming items. These items provide information to the user in a sort-of realtime fashion, but a specific value isn't that interesting. For example live or snapshot video images, or music progress as mentioned here. The individual value isn't directly interesting in a home automation context. And in most cases probably even only relevant when the user is looking. One could argue home automation is not about being a full-fledged media player, and I think the event based architecture isn't a optimal match for such systems. So for these kind of items it might be worth researching how these can be better supported. For example by having other types. For example for video a url to the livestream might be enough. (This is actual possible I think) For music progress maybe add an extra feature to the Player type. I don't know if these kind of issues have been discussed in the past so pardon my ignorance here :slightly_smiling_face:

[5iver]

The org.ops4j.pax.logging.cfg file is not in this repo, so this issue should move to openhab-distro. There is no logger for smarthome.event.ItemStateChangedEvent, but there is one for it's parent (smarthome.event) and its logging level is set to INFO. I agree with Rich and prefer things as they are to help troubleshoot default setups. If a user does not want this logging, they have several options to change the logging level or filter out specific logs. openHAB has a LOT of options available for fine tuning to a users specific needs and preferences, and logging is one of them.

[rkoshak]

The org.ops4j.pax.logging.cfg file is not in this repo, so this issue should move to openhab-distro.

But the Event Bus is in this repo and that is where the changes would have to be made to lower the logging level of the ItemChangeEvent, right? We can change what logging levels get shown in the pax.logging config, but we can't change at what level the log statements are made in the first place. Or maybe I don't understand the format of the config file as well as I think I do.

[Hilbrand]

@openhab-5iver I asked to put the issue here. It was first posted on openhab2-addons. This is indeed if the log level of this specific logging should be level INFO or DEBUG. (@rkoshak Thanks for reminding me with your comment this was my reason to put it here)

But I also wanted to have the discussion because I think the symptom is much more than just having to much logging. But the deeper issue here is how we should handle, what I call 'streaming' items, like video streams and progress (music, film). Maybe it's something that is considered outside the scope of openHAB. But than we can log it here for future references.

[blilleike]

For informational purposes only. I added two lines to org.ops4j.pax.logging.cfg

log4j2.logger.smarthomeItemStateChangedEvent.name = smarthome.event.ItemStateChangedEvent log4j2.logger.smarthomeItemStateChangedEvent.level = WARN

(directly above the EVENT logging configuration) This solved the issue for me. Whenever I need the events, I change that to INFO and see all the lines popping in. Definitely will stop my music while doing it ;)

Sorry this ended in the wrong repository.

[EliasGabrielsson]

I stumbled upon this discussion in the forum and in viewpoint of openHABian maintainer I made two conclusions.

OpenHabian, which aims to be an easy entry-point to openHAB, should maybe a) change the default level of logging to WARN from INFO to not wear out the SD-cards. This could however leave out important information so b) the user must be able to easy change level of log level. Related to this the log should also be easy consumeable, in the openHABian project we have "ductape" solved this by the Frontail service.

Questions followed by this reasoning:

• Are there a REST endpoint to change the log level?
• @ghys Have you planned to implement a setting in the new GUI to change log level?
• @ghys Will you have a Frontail like way of streaming the log into the UI?

[5iver]

An addon for the Karaf webconsole may help with this and also provide a web version of the Karaf console... https://community.openhab.org/t/openhabian-karaf-webconsole/31424. The OOTB interface is not very user friendly, but it's something to start with.

[ghys]

Are there a REST endpoint to change the log level? @ghys Have you planned to implement a setting in the new GUI to change log level? @ghys Will you have a Frontail like way of streaming the log into the UI?

As I replied in your other issue, any feature however desirable need backend support, the UI merely exposes it. It should and will not rely on anything outside what's provided by the well-known REST API (+ SSE & other core servlets). If there is ever a consensus to extend the API with this functionality and it ultimately gets added, then the UI will likely support it of course.

However, as an alternative, in this particular case, this could also be detecting and plugging into the Karaf webconsole' API: http://localhost:8080/system/console/logs, if it ever gets officially supported - even as an optional feature - as part of the openHAB distribution. This is acceptable because the endpoints are well-known.