Change the default logging level to INFO for org.openhab.automation.script

[jimtng]

Currently org.openhab.automation.script log level is TRACE by default as set in

openhab-distro/launch/app/runtime/log4j2.xml

Line 91 in 995fe61

<Logger level="TRACE" name="org.openhab.automation.script" />

IMO, This should be changed to INFO so that the default logging setting is usable for scripting engines/libraries without flooding the log with excessive details by default.

[jimtng]

@digitaldan WDYT about changing the default log level for org.openhab.automation.script to INFO? Within the jruby helper library, we extensively use trace, and they shouldn't show up as default. Even if user scripts were to use TRACE level, I'm sure it's not meant to show up by default. TRACE should only be enabled during debugging.

[digitaldan]

Is this currently a problem ? AFAIK this should only be used for user based scripts, and I am not expecting users to have to fiddle with changing the system log levels as there is not a built in way of doing that in the UI. If non user based scripts , like bindings , are logging to this prefix then I would agree this is an issue .

[jimtng]

I understand that this prefix is for user based scripts, and that's exactly what we're going to use it for. Currently jruby scripts logs to jsr223.jruby. This is an arbitrary prefix selected because nothing was suitable / available for it. Unfortunately this means we have to instruct users to enable this prefix manually, i.e. log:set INFO jsr223.jruby.

When org.openhab.automation.script was added, I thought it would be the perfect prefix to use, especially if it's already enabled out of the box, thus users no longer need to set it manually.

I agree that users shouldn't have to fiddle with system log levels. That's why the default should be INFO, not TRACE. TRACE logs should not show up out of the box by default, whether it is user scripts or binding.

So I am proposing here to change it to INFO, otherwise we won't be able to take advantage of this prefix, because the helper library uses a lot of trace level logging and we wouldn't want to flood the log out of the box with trace level logs.

[robnielsen]

I'm now seeing the following in my openhab.log after converting from dsl to jsscripting. My scripts are not logging anything:

2022-01-12 08:02:17.374 [DEBUG] [org.openhab.automation.script.rules ] - Extracted event payload [object Object]
2022-01-12 08:02:17.395 [DEBUG] [org.openhab.automation.script.items ] - Posted update DOWN to garageDoor1ga
2022-01-12 08:02:17.417 [DEBUG] [org.openhab.automation.script.items ] - Posted update 1.6419961374E12 to garageDoor1TimeStamp
2022-01-12 08:02:17.443 [DEBUG] [org.openhab.automation.script.rules ] - Extracted event payload [object Object]
2022-01-12 08:02:17.469 [DEBUG] [org.openhab.automation.script.items ] - Posted update DOWN to garageDoor1ga
2022-01-12 08:02:17.498 [DEBUG] [org.openhab.automation.script.items ] - Posted update 1.641996137474E12 to garageDoor1TimeStamp
2022-01-12 08:02:22.713 [DEBUG] [org.openhab.automation.script.rules ] - Extracted event payload [object Object]
2022-01-12 08:02:23.217 [DEBUG] [org.openhab.automation.script.rules ] - Extracted event payload [object Object]

Also garageDoor1TimeStamp is a DateType item.

[digitaldan]

So our original intention was that this would be used solely for user provided scripts, not libraries like openhab-js, and we wanted to make sure that console.debug(...) would work out of the box for users, along with the other console log levels since this is familiar to many JS users. Since there is not an easy way to change debugging levels, this seemed the most user friendly approach and would not affect anything else. I'm open to other ideas, but my intent is to keep people out of the karaf console or xml files if we can.

If we want this set to INFO , then we could simply remove it altogether, as thats the default for org.openhab , but i would probably still keep it in just for reference, and so it does not get changed in the future if the default level changes.

To be fair, most people will use console.log(...) , which defaults to INFO, so it's not a huge deal, but i would want maybe @rkoshak to pipe in as he might have an idea if this might be an issue for users.

I'm now seeing the following in my openhab.log

Those are bugs that slipped into the library, "Extracted event" was fixed a few days ago, and i just removed the "Posted update" , the JS Library should never be doing any logging on it own at any level.

[rkoshak]

I would vote to be consistent with the behavior of Rules DSL in this regard which sets the default level to INFO. That's pretty much the established default, at least for any users who have been using OH for any amount of time. I too was surprised when the level jumped down to TRACE because I've a lot of debug level statements in my rules I don't want to see on a regular basis but only when something isn't working.

It's probably OK to force users to have to go to the console or XML file for those rare users who want to differentiate between a trace/debug/info/warn/error logging in their rules. Those users are already going to be advanced enough that they can manage adjusting the level. And if it becomes too much of a problem, I can quickly write up a rule template or something to do it for them. ;-)

Those who don't care about levels are probably using logInfo (or equivalent) anyway because that's what works by default.

I think setting the default level to INFO is fine. Those user for whom getting to the console or config xml file is a problem will just use INFO. The rest probably don't have too much heart burn doing so. Just look back over the decade's worth of Rules DSL examples. How many statements do you ever see besides logInfo? Almost never.

the JS Library should never be doing any logging on it own at any level

While I agree with this for now, can we be sure that will always be the case? With my own rule templates and libraries that people use, having the ability to tell them to turn up the logging so I can get more information to debug problems is very useful.

From a user's perspective, getting meaningful error messages from the library might also be useful. I'm not sure I would make a blanket ban on logging in the helper libraries. Instead set a high bar to adding it should we need it in the future.

[jimtng]

If we want this set to INFO , then we could simply remove it altogether, as thats the default for org.openhab

The jruby helper library uses the same logger, and therefore prefix, as user scripts.

I suppose we could sidestep this issue for jruby helper library by simply using org.openhab.automation.jruby thus avoiding the org.openhab.automation.script completely, and rely on the fact that org.openhab is set to INFO by default.

[robnielsen]

Those are bugs that slipped into the library, "Extracted event" was fixed a few days ago, and i just removed the "Posted update" , the JS Library should never be doing any logging on it own at any level.

Good news, I also have "Sending command" entries in the log file as well.

[digitaldan]

So i did think about this more, and agree we should set the default logger to INFO as well to be consistant, i'll open a PR.