Log level on rule

Setup, Configuration and Use Runtime
1

Hi all,

is it possible to configure the log4j2.xml with independent log levels per rule?
I try to implement my rules with a good debugging concept. But if I develop on a new rule, I don’t want to see the logs of all other already productive rules.
Therefore I thought is possible to set the loglevel like this:

<Logger level="DEBUG" name="org.openhab.automation.openhab-js.[rule_id]">

But this is not working, only setting DEBUG on level ‘automation’ worked for me

2

Hi
What version of OH are you running?

There was a recent issue ([jsscripting] Logger name missing for UI-based rules · Issue #17165 · openhab/openhab-addons · GitHub) which has been addressed in one of the more recent snapshots.

This may the the cause?

3

Thank you, I will try to test if after an update.

But can some tell me, if I’m in the right module?
I tried org.openhab.automation.openhab-js.
in the ticket the another path is used: org.openhab.automation.script.ui.
So what path needs to be used for Blockly UI rules, what for filebased JS rules under automation/js

4

I looked at the opehab.log to see what the logs are listed under.

15:56:15.763 [INFO ] [penhab.automation.script.ui.GateClose] - Gate has Closed!
5

Blockly and UI JS Scripting rules use org.openhab.automation.script.ui.<ruleId>.

I think file based JS rules use org.openhab.automation.script.ui.<filename>. I’m not positive about that though.

You can change the logger name used by console on a script by script basis with the following line of code:

console.loggerName = "org.openhab.what.ever.you.want";

For my OHRT library I use org.openhab.automation.rulesTools and my rule tempaltes use org.openhab.automation.rules_tools.<Template Name>.<ruleId>.

So when I need to help someone I can have them change the logging just for the rule or all of the code they may be running from me.

Another hidden trick is you can actually change the logging level of the rule in the rule.

osgi.getService('org.apache.karaf.log.core.LogService').setLevel(console.loggerName, 'DEBUG');

However, there are come cautions:

  • if the rule uses the same logger name as another, the logging level goes up for both, which should be expected really.
  • don’t do this all the time because every time the rule runs it will edit the file. I have seen that if two rules try to change their logging level too close together it wipes out the log4j2.xml file entirely. So add this line, run the rule once, then comment it out until you want to change the logging level again.

Of course, you can change the logging level all the other usual ways too.

1 Like
6

I bookmarked this post for this reason :wink:

7

That sounds like a bug in log4j?

8

Possibly. I think it’s more likely a problem in pax. I don’t think log4j2 actually supports rewriting the config file like karaf does natively.

What appears to be happening is if one rule runs and changes the logger name, that causes something to edit the log4j2.xml file (all runtime changes to the logging does this whether it’s through the REST API, the karaf console, or from a rule). However, if the timing is just right where one rule is in the act of writing a new log4j2.xml file when another rule wants to start writing too, the file itself ends up blank as a result of the conflict.

It doesn’t really make a whole lot of sense to change the logger level inside of the rule itself every time it runs anyway so there is a strong argument that it’s not a bug but a misuse.

9

I came across this thread while searching for answers on this topic. I’m trying to debug a rule and would like to increase the logging for that rule. Before modifying the logging for the rule under investigation, I modified a test rule (rule ID “Test_Rule”) so that I could see the effect of changing the log level using a rule that I can quickly and repeatedly run. I went into karaf and entered “log:set DEBUG org.openhab.automation.script.ui.Test_Rule” I then pressed the test button and saw no extra log entries at all. I Then changed the log level to TRACE and still no extra entries in the log. The test rule contains one condition in the “But only if” section. Perhaps I have the wrong expectation, but I was hoping to at least see that the rule checked the condition. Am I doing something wrong, or do I have the wrong expectation of logs for UI rules?

10

You have the wrong explectation for what to get from logging for rules. Setting the log level for a rule like that changes what gets logged from inside that rule. Your console.info, .debug, .trace statements if using JS or logInfo, logDebug, logTrace statements if using Rules DSL. It doesn’t change what OH core logs as those are different loggers.

You can either add some logging statements to your condition to see that the condition was run, or you need to find the names of the loggers in OH core and the automation add-on you are using for your rules to see what each of those are doing respectively. But be aware that those will log for all rules, not just the one.

I find it easiest to just add the logging to the rule itself since you can control it on a rule-by-rule basis.

One thing you can do to see that rules are getting triggered is to change the logging level for openhab.event.RuleStatusInfoEvent to INFO. That will add the rule started and rule idle events to events.log every time any rule runs.

11

Thanks for the clarification, Rich. I have made it a habit of adding logging statements to my rules, but I wanted to see if the conditions are checked when the rule runs. I have been choosing Item Condition for the condition, but I can use Script Condition instead and include logging statements in that.