[Solved] Jython Logging - Changed between 2.5.3 and 2.5.5?

Tags: #<Tag:0x00007f617e4272f0>

Has anyone else had an issue with the Jython logging no longer producing simple function.log.info statements?

I was running OH2.5.3 via OpenHABian on an Ubuntu server and then got an update to the newer OH2.5.5. On restart my logs are missing the *.log.info output.

My Jython test code:

@rule("Testing stuff - v1")
@when("Item RunJython1 changed")
def testing_1(event):
    """ Just random code snippets to test stuff """
    testing_1.log.info("Starting 1")

    home = items["IsAnyoneHome"]
    holiday = items["IsVacation"]

    logging.warning("Simple - Home is {}".format(home))
    logging.warning("Simple - Holiday is {}".format(holiday))

    if items["IsAnyoneHome"] == ON:
        logging.warning("Logic - Home is on")
    elif items["IsAnyoneHome"] == OFF:
        logging.warning("Logic - Home is off")

    if items["IsVacation"] == ON:
        logging.warning("Logic - Holiday is on")
    elif items["IsVacation"] == OFF:
        logging.warning("Logic - Holiday is off")

    testing_1.log.info("Ending 1")

In OH2.5.3

2020-05-20 08:38:22.762 [INFO ] [jsr223.jython.Testing stuff - v1    ] - Starting 1
2020-05-20 08:38:22.768 [WARN ] [ROOT                                ] - Simple - Home is ON
2020-05-20 08:38:22.769 [WARN ] [ROOT                                ] - Simple - Holiday is OFF
2020-05-20 08:38:22.771 [WARN ] [ROOT                                ] - Logic - Home is on
2020-05-20 08:38:22.773 [WARN ] [ROOT                                ] - Logic - Holiday is off
2020-05-20 08:38:22.775 [INFO ] [jsr223.jython.Testing stuff - v1    ] - Ending 1
2020-05-20 08:38:22.776 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'f94b9e05-c06b-4474-ad78-287da196a6e3' is executed.

The same Jython function now running in OH2.5.5:

2020-05-20 09:09:02.462 [WARN ] [ROOT                                ] - Simple - Home is OFF
2020-05-20 09:09:02.464 [WARN ] [ROOT                                ] - Simple - Holiday is OFF
2020-05-20 09:09:02.466 [WARN ] [ROOT                                ] - Logic - Home is off
2020-05-20 09:09:02.468 [WARN ] [ROOT                                ] - Logic - Holiday is off
2020-05-20 09:15:24.699 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule '826edb45-f437-4d35-9e2e-b2e47da5105c' is executed.

So the start and end log functions,

testing_1.log.info("Starting 1")
...
testing_1.log.info("Ending 1")

no longer generate output.

I have been able to replicate this using OSX runtimes on my Dev machine. No karaf settings changed between the update, and the internal RuleEngine DEBUG messages are still appearing - just not the ones I add to my functions.

Double check your loggers (log:get)… they may have been overwritten. Also, have you restarted a second time since the update? Another thing you could try is to use the beta Jython addon…

I have restarted, but I hadn’t checked the logger state. The Ubuntu (Production) box lists the following:

Logger                                                                  │ Level
────────────────────────────────────────────────────────────────────────┼──────
ROOT                                                                    │ WARN
javax.jmdns                                                             │ ERROR
javax.mail                                                              │ ERROR
jsr223                                                                  │ DEBUG
jsr223.jython.core                                                      │ DEBUG
jsr223.jython.core.metadata                                             │ INFO
jsr233                                                                  │ DEBUG
org.apache.karaf.jaas.modules.audit                                     │ INFO
org.apache.karaf.kar.internal.KarServiceImpl                            │ ERROR
org.apache.karaf.shell.ssh.SshUtils                                     │ ERROR
org.apache.karaf.shell.support                                          │ OFF
org.eclipse.lsp4j                                                       │ OFF
org.eclipse.smarthome                                                   │ INFO
org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl │ DEBUG
org.jupnp                                                               │ ERROR
org.openhab                                                             │ INFO
org.openhab.core.automation                                             │ DEBUG
org.openhab.ui.paper                                                    │ WARN
org.openhab.ui.paper.internal                                           │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver                      │ ERROR
org.ops4j.pax.web.pax-web-runtime                                       │ OFF
smarthome.event                                                         │ INFO
smarthome.event.InboxUpdatedEvent                                       │ ERROR
smarthome.event.ItemAddedEvent                                          │ ERROR
smarthome.event.ItemRemovedEvent                                        │ ERROR
smarthome.event.ItemStateEvent                                          │ ERROR
smarthome.event.ThingAddedEvent                                         │ ERROR
smarthome.event.ThingRemovedEvent                                       │ ERROR
smarthome.event.ThingStatusInfoEvent                                    │ ERROR

So jsr233 is in twice, with jsr223.jython.core & jsr223.jython.core.metadata.

Running the test rules (x3) again, still doesn’t give me the testing.log.info output I’d expect.

I might kick the prod box again and see what happens to the loggers.

The dev runtime on OSX has been re-downloaded and configured ( I should really automate some of that!) and the jsr233 & core.automation are now present and appear to be working.

Kicked the OpenHAB service twice now with no change to the duplicate jsr233 loggers and still no joy with the testing output.

I’ll physically restart the entire box now and wait for that to come back up.

[UPDATE]

Box has been physically restarted, no change.

I’ve spun up another dev environment based on 2.5.5 and installed the Beta .jar. I’ll have a play.

Thanks for all the work on this BTW!

Check permissions on all of the files (what type of installation are you running?) and manually edit the $OPENHAB_USERDATA/etc/org.ops4j.pax.logging.cfg file.

You are very welcome!

My prod box is Ubuntu server 18.04 LTS running openhabian. Current 2.5.5-1 release of OpenHAB.

My dev environments are the OSX runtimes. That way I can spin up a new dev environment, copy my .things, .items etc etc across and then just try stuff.

I used to use a RPi, but reload/deployment times when testing was too long!!

Anyway, my permissions were OK, I even ran the openhabian fix permissions config item to make sure.

Eventually I compared the Dev /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg with the one on Prod, and apart from the extra jsr223 entry I could see no differences, so I’ve now copied the file across and restarted.

This appears to have solved the issue - I can see all the things that don’t work now!

On a side note - the custom loggers you discuss here - do these go in the pax.logging.cfg file and replace the existing jsr223 entries? Will these create separate log files for the jsr233 and automation loggers or still in the normal openhab.log?

Yes. If there are duplicates, the last entry in the file takes precedence.

They will log to separate files based on the appender. If additivity is true, then they will also log to the openhab.log. More details in the docs…

1 Like