[SOLVED] Jython Logging

Tags: #<Tag:0x00007f616e2f6cd8> #<Tag:0x00007f616e2f6b20>

I have successfully installed jsr223 with Jython following the tutorial at: https://openhab-scripters.github.io/openhab-helper-libraries/Getting%20Started/Installation.html

All is well and the hello world rule executes fine.

BUT…
There is a bit of log spamming. Everytime the rules executes I get two lines in the log:

2019-11-06 12:31:00.853 [.event.RuleStatusInfoEvent] - 589d0dd5-f662-47f5-b6d7-b94ce5e686ae updated: RUNNING
2019-11-06 12:31:00.870 [.event.RuleStatusInfoEvent] - 589d0dd5-f662-47f5-b6d7-b94ce5e686ae updated: IDLE

I have set the logging to:
in the console:

log:set WARN org.openhab.core.automation
log:set INFO jsr223

But the log lines still appear. Any way to remove them, please?

I thought the purpose of logging war to log what happens for historical and troubleshooting purposes. In that case, the lines make perfect sense.
What do you see as the purpose of logging?

Thanks, I know what logging is for.
I don’t want these two lines. I know the rule is running if stuff happens (or not)
I intend to migrate all my rules to jython in the near future and there will be thousands of those lines spamming my log file. I don’t want them

I’ve setup loggers and appenders so that my automation logging goes to two separate files, one for core and one for jsr223. Let me know if you are interested in those. This helps a lot! It looks like you are viewing both the openhab.log and events.log, so you could turn off the logging for…

log4j2.logger.smarthome_event_RuleStatusInfoEvent.name = smarthome.event.RuleStatusInfoEvent
log4j2.logger.smarthome_event_RuleStatusInfoEvent.level = WARN

:partying_face:

1 Like

Thanks that did the trick.
I’ll have a look at your custom loggers, please
I think they’ll come handy in the near future.

Now I need to brush up on my python…

BTW: would that work?

    if items.Loft_Hatch == OPEN:
        events.sendCommand("Loft_Light", "ON")
    else:
        events.sendCommand("Loft_Light", "OFF")

Or does it need to be "OPEN" with quotes?

Think I found the answer there: https://www.openhab.org/docs/configuration/jsr223.html#default-preset-importpreset-not-required

OPEN is preset. Without quote.

Here you go. I also comment out the ‘Common pattern layout for appenders’ section at the top, so that I can see the full name of the loggers.

log4j2.logger.RuleEngineImpl.name = org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl
log4j2.logger.RuleEngineImpl.level = DEBUG
log4j2.logger.RuleEngineImpl.additivity = false
log4j2.logger.RuleEngineImpl.appenderRefs = Rules
log4j2.logger.RuleEngineImpl.appenderRef.Rules.ref = jsr223

log4j2.logger.jsr223.name = jsr223
log4j2.logger.jsr223.level = DEBUG
log4j2.logger.jsr223.additivity = false
log4j2.logger.jsr223.appenderRefs = JSR223
log4j2.logger.jsr223.appenderRef.JSR223.ref = RULES

log4j2.logger.jython_core.name = jsr223.jython.core
log4j2.logger.jython_core.level = DEBUG
log4j2.logger.jython_core.additivity = false
log4j2.logger.jython_core.appenderRefs = Jython_Core
log4j2.logger.jython_core.appenderRef.Jython_Core.ref = jsr223

log4j2.logger.jython_core_metadata.name = jsr223.jython.core.metadata
log4j2.logger.jython_core_metadata.level = INFO
log4j2.logger.jython_core_metadata.additivity = false
log4j2.logger.jython_core_metadata.appenderRefs = Jython_Core_Metadata
log4j2.logger.jython_core_metadata.appenderRef.Jython_Core_Metadata.ref = jsr223

log4j2.logger.groovy_core.name = jsr223.groovy.core
log4j2.logger.groovy_core.level = DEBUG
log4j2.logger.groovy_core.additivity = false
log4j2.logger.groovy_core.appenderRefs = Groovy_Core
log4j2.logger.groovy_core.appenderRef.Groovy_Core.ref = jsr223

log4j2.logger.javascript_core.name = jsr223.javascript.core
log4j2.logger.javascript_core.level = DEBUG
log4j2.logger.javascript_core.additivity = false
log4j2.logger.javascript_core.appenderRefs = Javascript_Core
log4j2.logger.javascript_core.appenderRef.Javascript_Core.ref = jsr223

log4j2.logger.ESHAutomation.name = org.eclipse.smarthome.automation
log4j2.logger.ESHAutomation.level = INFO
log4j2.logger.ESHAutomation.additivity = false
log4j2.logger.ESHAutomation.appenderRefs = ESHAutomation
log4j2.logger.ESHAutomation.appenderRef.ESHAutomation.ref = jsr223

log4j2.logger.Automation.name = org.openhab.core.automation
log4j2.logger.Automation.level = INFO
log4j2.logger.Automation.additivity = false
log4j2.logger.Automation.appenderRefs = Automation
log4j2.logger.Automation.appenderRef.Automation.ref = jsr223

log4j2.logger.python.name = org.python
log4j2.logger.python.level = DEBUG
log4j2.logger.python.additivity = false
log4j2.logger.python.appenderRefs = Python
log4j2.logger.python.appenderRef.Python.ref = jsr223

# Rules
log4j2.appender.Rules.name = RULES
log4j2.appender.Rules.type = RollingRandomAccessFile
log4j2.appender.Rules.fileName = ${openhab.logdir}/rules/rules.log
log4j2.appender.Rules.filePattern = ${openhab.logdir}/rules/rules.log.%d{yyyyMMddHHmmss}
log4j2.appender.Rules.immediateFlush = true
log4j2.appender.Rules.append = true
log4j2.appender.Rules.layout.type = PatternLayout
log4j2.appender.Rules.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%c] - %m%n
log4j2.appender.Rules.policies.type = Policies
log4j2.appender.Rules.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Rules.policies.size.size = 10MB
log4j2.appender.Rules.strategy.type = DefaultRolloverStrategy
log4j2.appender.Rules.strategy.max = 10
#log4j2.appender.Rules.encoding = UTF-8

# jsr223
log4j2.appender.jsr223.name = jsr223
log4j2.appender.jsr223.type = RollingRandomAccessFile
log4j2.appender.jsr223.fileName = ${openhab.logdir}/jsr223/jsr223.log
log4j2.appender.jsr223.filePattern = ${openhab.logdir}/jsr223/jsr223.log.%d{yyyyMMddHHmmss}
log4j2.appender.jsr223.immediateFlush = true
log4j2.appender.jsr223.append = true
log4j2.appender.jsr223.layout.type = PatternLayout
log4j2.appender.jsr223.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%c] - %m%n
log4j2.appender.jsr223.policies.type = Policies
log4j2.appender.jsr223.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.jsr223.policies.size.size = 10MB
log4j2.appender.jsr223.strategy.type = DefaultRolloverStrategy
log4j2.appender.jsr223.strategy.max = 10

Yes, that looks like it will work. Check here for a list of the things that are included in the default script scope. This will also work…

events.sendCommand("Loft_Light", "ON" if items.Loft_Hatch == OPEN else "OFF")
1 Like

Thanks a lot…

It works

I’ll keep these loggers for the near future
In the mean time, I start changing my rules over.
The first one is done and working

Onwards and upwards

1 Like

Excellent! Just shout if you have questions or issues!

I will, expect to hear from me quite a bit in the next few weeks.

1 Like

I’ll just pipe in to mention that those log statements are coming from events.log and therefore reflect events that are occurring on the event bus. So it is fairly reasonable for these lines to appear in events.log. However, mapping a Rule’s UUID with it’s more human friendly name is a pain so the current utility of these log statements is pretty low.

@5iver, is it possible to replace the UUID with the Rule name at all or are we stuck with the UUID? I realize this might require a PR to the core to change the line that logs that out. I did a quick search and couldn’t find the line, or don’t know enough to recognize the line.

1 Like

You’d think the simplest thing to do would be to just add the rule’s name to the log entry. Unfortunately, the rule name is not available everywhere it would be needed to include in the logs, so this is not quick and easy. I worked on this a bit last year and had something partially working (there are some commits somewhere… probably in ESH), but ended up scrapping it, since I preferred putting the effort into making the rule UIDs configurable. Early on, the rule ID could be set and there are some remnants of this in the Python helper libraries. Currently, it cannot be set when SimpleRule is used and this is somewhere near the bottom of my backlog :slightly_smiling_face:.

The UIDs of triggers are configurable, so I included friendly names for the triggers in the Python decorators. I’ll do the same with the rule names when their UIDs are configurable…

2019-11-06 10:38:46.257 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The trigger 'Item-HEM1_Total_Power-changed_f39ec971fd0e11e9aeb0001bb952f560_f39ec972fd0e11e9a861001bb952f560' of rule '0fedf70d-9d58-40f9-8aff-a6a29b2ea303' is triggered.
2019-11-06 10:38:46.258 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule '0fedf70d-9d58-40f9-8aff-a6a29b2ea303' is executed.
2019-11-06 10:38:47.546 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The trigger 'Item-Weather_SolarRadiation-received-update_b553430fff9a11e99056001bb952f560_b5534310ff9a11e99b8d001bb952f560' of rule 'ef1d3c1f-3911-4656-b1e9-a882fa06f951' is triggered.
2019-11-06 10:38:47.548 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule 'ef1d3c1f-3911-4656-b1e9-a882fa06f951' is executed.
2019-11-06 10:38:47.557 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule 'd36c700a-69a7-4c0a-b2ec-655d73314bd1' is executed.
2019-11-06 10:38:47.558 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The trigger 'Item-Weather_SolarRadiation_Corrected-changed_e32f540ffd0e11e99bf6001bb952f560_e32f5410fd0e11e98991001bb952f560' of rule 'd36c700a-69a7-4c0a-b2ec-655d73314bd1' is triggered.
2019-11-06 10:39:05.799 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The trigger 'Time_cron_5_0_3_e576ac00fd0e11e9bf64001bb952f560_e576ac01fd0e11e9b371001bb952f560' of rule '3cce1729-4479-4eff-8c0f-9857abc61a29' is triggered.
2019-11-06 10:39:06.212 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule '3cce1729-4479-4eff-8c0f-9857abc61a29' is executed.
2019-11-06 10:39:16.249 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The trigger 'Item-HEM1_Total_Power-changed_f39ec971fd0e11e9aeb0001bb952f560_f39ec972fd0e11e9a861001bb952f560' of rule '0fedf70d-9d58-40f9-8aff-a6a29b2ea303' is triggered.
2019-11-06 10:39:16.252 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule '0fedf70d-9d58-40f9-8aff-a6a29b2ea303' is executed.

That was going to be my next question. I agree, making them configurable would be an even better approach. There is no reason why it has to be a UUID. It only needs to be unique within that instance of OH so human readable names should be sufficient.

It also cannot be set in PaperUI.

To ensure they are unique, I will set the rule’s UID to a combination of the rule’s name and a randomly generated ID, as is done with the triggers.

I believe it could be though, if the rule UID was included as an editable field in the UI. Only scripted automation uses SimpleRule.

1 Like