Logging in openHAB 3

I agree. I asked @wborn here if he considered it when doing the conversion to the new xml file format.

1 Like

PR was submitted so should be in a SNAPSHOT build soon.

Thanks @Rodelkoenig for pointing this out!

2 Likes

For the benefit of anyone who comes along and wants to do this, the modification is in the first line.

This:

<?xml version="1.0" encoding="UTF-8" standalone="no"?><Configuration>

Becomes this:

<?xml version="1.0" encoding="UTF-8" standalone="no"?><Configuration monitorInterval="30">

Also, I now understand why 30 seconds is reasonable, given this statement:

the configuration file will be checked for changes only after at least 30 seconds have elapsed

I missed seeing that earlier.

For slow copy-paste people like me :wink: , here is a working example for z-wave.
I also found out the hard way that it is important to add each section at the end (Appenders and Loggers).

/var/lib/openhab/etc/log4j2.xml (Debian systems)
Appender part

 <!-- Z-wave appender -->
                <RollingRandomAccessFile append="true" fileName="${sys:openhab.logdir}/zwave.log" filePattern="${sys:openhab.logdir}/zwave.log.%i" immediateFlush="true" name="ZWAVE">
                        <PatternLayout>
                                <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n</Pattern>
                        </PatternLayout>
                        <Policies>
                                <SizeBasedTriggeringPolicy size="16 MB"/>
                        </Policies>
                        <DefaultRolloverStrategy max="8"/>
                </RollingRandomAccessFile>
<!-- Z-wave -->

Logger part

<!-- Z-wave Logger -->
                <Logger additivity="false" level="DEBUG" name="org.openhab.binding.zwave">
                        <AppenderRef ref="ZWAVE"/>
                </Logger>
<!-- Z-wave -->
4 Likes

Hi All,
First of all i want to say thanks to all for the input and @rockit4 for the “Copy/paste” Template and (for me) the most important hint to add the lines at the and of each section. I first added the lines in my well structed way (not at the end of each section) and it didn’t work. I tried many combinations, openhab.service restarts and even reboots of the whole environment. Nothing worked. So i read the last post carefully and there it was.

I also found out the hard way that it is important to add each section at the end (Appenders and Loggers).

Thanks for such a great community!

1 Like

Glad i could be of help :slight_smile:
Personally I love when someone has taken the time to write an example ready to go.
Copy/paste and you are up and running without the need to read the book how to do it.
You could argue that being lazy is the driving force of home automation :parasol_on_ground:

1 Like

I think it needs one reboot after adding that in the file. I added it but it doesn’t filter any of my events. Is there a possibility to restart the logging service (apache i think?).

Sorry to revive an old post. I tried to adapt @rockit4 ZWAVE code for RFXCOM binding, I’m no longer able to find its logs since update to OH3 (very useful to identify protocols). This is what I added in Appenders section :

                 <!-- RFXCOM appender -->
                <RollingRandomAccessFile append="true" fileName="${sys:openhab.logdir}/rfxcom.log" filePattern="${sys:openhab.logdir}/rfxcom.log.%i" immediateFlush="true" name="RFXCOM">
                        <PatternLayout>
                                <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n</Pattern>
                        </PatternLayout>
                        <Policies>
                                <SizeBasedTriggeringPolicy size="16 MB"/>
                        </Policies>
                        <DefaultRolloverStrategy max="8"/>
                </RollingRandomAccessFile>
                <!-- RFXCOM -->
        </Appenders>

And in loggers :

                <!-- RFXCOM Logger -->
                <Logger additivity="false" level="DEBUG" name="org.openhab.binding.rfxcom">
                        <AppenderRef ref="RFXCOM"/>
                </Logger>
                <!-- RFXCOM -->
        </Loggers>

Is anyone having the same issue ? I’d gladly appreciate some help, some chinese unknown 433.92 Mhz things are still on the shelves.

I also battled with logging etc. Edited my /userdata/etc/org.ops4j.pax.logging.cfg to be as follows:

org.ops4j.pax.logging.log4j2.config.file=${karaf.etc}/log4j2.xml

This seemed to resolve the issues I had setting logging via log4j2.xml

I am running on Windows 10.

Not sure if the upgrade fails to correctly update the file?

In my case, upgrade seems to have taken care of updating the file, its content is the same as yours after modification.

I’m in the process of building an OH3.1 system from scratch, my 2.5 system is a bit crufty so I’ve chosen not to upgrade it.

I have a few custom log appenders in my 2.5 system, for example:

# Security
log4j2.logger.security.name = org.eclipse.smarthome.model.script.security
log4j2.logger.security.level = DEBUG
log4j2.logger.security.additivity = false
log4j2.logger.security.appenderRefs = security
log4j2.logger.security.appenderRef.security.ref = SECURITY

That I use with, for example, the following python code:

    log = logging.getLogger("org.eclipse.smarthome.model.script.security")
    log.info("SECURITY: Sunset/sunrise event triggered, event.channel is (" + str(event.channel) + ").")

This lets me use different log files for different groups of rules and stops openhab.log getting overloaded with every message any of my many rules produce.

Since the removal of the eclipse smarthome namespace from what should I put in my OH3 appender? Would it be:

	<!-- SECURITY -->
-<Logger name="org.openhab.core.model.script.security" level="DEBUG" additivity="false">
	<AppenderRef ref="SECURITY"/>
</Logger>

I’ve tried that but it doesn’t seem to be correct, any python rule that tries to log to security.log triggers an exception. Any ideas?

What’s the exception? Your python code can create and use any arbitrary log name regardless of how the log4j2.xml file is configured. The use of the package names of the classes for the logger name is a matter of convention. Referring to loggers that are not configured to log should not generate an error. If you are seeing exceptions in your rules, it’s because there is something wrong with your rule, not the logger config.

But all of that is just conjecture without seeing the actual error.

The rule that’s causing the exception is the bottom one of these two “@when(“Item isNight received update”)”, I’ve commented out all the code in it except for the log statements because the items it updates don’t exist yet:

from core.rules import rule
from core.triggers import when

@rule("Jython IsItDark", description="This triggers the isNight Switch based on sunrise and sunset times")
@when("Channel astro:sun:local:set#event triggered START")
@when("Channel astro:sun:local:rise#event triggered START")
def is_it_dark(event):

    log = logging.getLogger("org.eclipse.smarthome.model.script.security")
    # remotecontrolkitchennexa1rule.log.info("lightingPresetKitchen state is (" + str(ir.getItem("lightingPresetKitchen").state) + ").")
    log.info("SECURITY: Sunset/sunrise event triggered, event.channel is (" + str(event.channel) + ").")

    # events.sendCommand("isNight", "ON" if "set" in str(event.channel).split(":") else "OFF")
    if "set" in str(event.channel):
        log.info("SECURITY: event.channel contains string (set), setting item isNight to ON")
        events.sendCommand("isNight", "ON")
    else:
        log.info("SECURITY: event.channel doesn't contain string (set), setting item isNight to OFF")
        events.sendCommand("isNight", "OFF")

@rule("isNight State Changed", description="This triggers the isNight Switch based on sunrise and sunset times")
@when("Item isNight received update")
def isNight_received_update(event):

    log = logging.getLogger("org.openhab.core.model.script.security")

    if event.itemState == ON:
        log.info("SECURITY: Night time begins....")
        # events.sendCommand("DoorbirdD101_Light", "ON")
        # events.postUpdate("lighting_hallway_PIR_timeout_minutes", "1")
    else:
        log.info("SECURITY: Night time ends....")
        # events.sendCommand("DoorbirdD101_Light", "OFF")
        # events.postUpdate("lighting_hallway_PIR_timeout_minutes", "1")

If I toggle the isNight item manually via a widget I see a whole load of error messages appear in the log:

        at org.python.core.PyTableCode.call(PyTableCode.java:173) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:119) ~[?:?]
        at org.python.core.PyFunction.__call__(PyFunction.java:406) ~[?:?]
        at core.jsr223$py.__getattr__$6(/etc/openhab/automation/lib/python/core/jsr223.py:63) ~[?:?]
        at core.jsr223$py.call_function(/etc/openhab/automation/lib/python/core/jsr223.py) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:173) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:150) ~[?:?]
        at org.python.core.PyFunction.__call__(PyFunction.java:426) ~[?:?]
        at org.python.core.PyMethod.__call__(PyMethod.java:141) ~[?:?]
        at org.python.core.PyMethod.__call__(PyMethod.java:132) ~[?:?]
        at org.python.core.Deriveds.__findattr_ex__(Deriveds.java:73) ~[?:?]
        at org.python.core.PyModuleDerived.__findattr_ex__(PyModuleDerived.java:1009) ~[?:?]
        at org.python.core.PyObject.__findattr__(PyObject.java:902) ~[?:?]
        at org.python.core.PyObject.__findattr__(PyObject.java:889) ~[?:?]
        at org.python.core.imp.ensureFromList(imp.java:1484) ~[?:?]
        at org.python.core.imp.ensureFromList(imp.java:1449) ~[?:?]
        at org.python.core.imp.import_module_level(imp.java:1377) ~[?:?]
        at org.python.core.imp.importName(imp.java:1528) ~[?:?]
        at org.python.core.ImportFunction.__call__(__builtin__.java:1285) ~[?:?]
        at org.python.core.PyObject.__call__(PyObject.java:433) ~[?:?]
        at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
        at org.python.core.imp.importFromAs(imp.java:1620) ~[?:?]
        at org.python.core.imp.importFrom(imp.java:1595) ~[?:?]
        at core.osgi$py.f$0(/etc/openhab/automation/lib/python/core/osgi/__init__.py:92) ~[?:?]
        at core.osgi$py.call_function(/etc/openhab/automation/lib/python/core/osgi/__init__.py) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:173) ~[?:?]
        at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
        at org.python.core.imp.createFromCode(imp.java:630) ~[?:?]
        at org.python.core.imp.createFromPyClass(imp.java:312) ~[?:?]
        at org.python.core.imp.createFromPyClass(imp.java:255) ~[?:?]
        at org.python.core.imp.loadFromSource(imp.java:929) ~[?:?]
        at org.python.core.imp.find_module(imp.java:769) ~[?:?]
        at org.python.core.PyModule.findSubModule(PyModule.java:140) ~[?:?]
        at org.python.core.PyModule.impAttr(PyModule.java:107) ~[?:?]
        at org.python.core.imp.import_next(imp.java:1161) ~[?:?]
        at org.python.core.imp.ensureFromList(imp.java:1486) ~[?:?]
        at org.python.core.imp.ensureFromList(imp.java:1449) ~[?:?]
        at org.python.core.imp.import_module_level(imp.java:1377) ~[?:?]
        at org.python.core.imp.importName(imp.java:1528) ~[?:?]
        at org.python.core.ImportFunction.__call__(__builtin__.java:1285) ~[?:?]
        at org.python.core.PyObject.__call__(PyObject.java:433) ~[?:?]
        at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
        at org.python.core.imp.importFromAs(imp.java:1620) ~[?:?]
        at org.python.core.imp.importFrom(imp.java:1595) ~[?:?]
        at core.actions$py.f$0(/etc/openhab/automation/lib/python/core/actions.py:59) ~[?:?]
        at core.actions$py.call_function(/etc/openhab/automation/lib/python/core/actions.py) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:173) ~[?:?]
        at org.python.core.PyCode.call(PyCode.java:18) ~[?:?]
        at org.python.core.imp.createFromCode(imp.java:630) ~[?:?]
        at org.python.core.imp.createFromPyClass(imp.java:312) ~[?:?]
        at org.python.core.imp.createFromPyClass(imp.java:255) ~[?:?]
        at org.python.core.imp.loadFromSource(imp.java:929) ~[?:?]
        at org.python.core.imp.find_module(imp.java:769) ~[?:?]
        at org.python.core.PyModule.findSubModule(PyModule.java:140) ~[?:?]
        at org.python.core.PyModule.impAttr(PyModule.java:107) ~[?:?]
        at org.python.core.imp.import_next(imp.java:1161) ~[?:?]
        at org.python.core.imp.import_logic(imp.java:1278) ~[?:?]
        at org.python.core.imp.import_module_level(imp.java:1369) ~[?:?]
        at org.python.core.imp.importName(imp.java:1528) ~[?:?]
        at org.python.core.ImportFunction.__call__(__builtin__.java:1285) ~[?:?]
        at org.python.core.PyObject.__call__(PyObject.java:433) ~[?:?]
        at org.python.core.__builtin__.__import__(__builtin__.java:1232) ~[?:?]
        at org.python.core.imp.importOne(imp.java:1547) ~[?:?]
        at core.log$py.wrapper$7(/etc/openhab/automation/lib/python/core/log.py:114) ~[?:?]
        at core.log$py.call_function(/etc/openhab/automation/lib/python/core/log.py) ~[?:?]
        at org.python.core.PyTableCode.call(PyTableCode.java:173) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:306) ~[?:?]
        at org.python.core.PyBaseCode.call(PyBaseCode.java:197) ~[?:?]
        at org.python.core.PyFunction.__call__(PyFunction.java:485) ~[?:?]
        at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237) ~[?:?]
        at org.python.core.PyMethod.__call__(PyMethod.java:228) ~[?:?]
        at org.python.core.PyMethod.__call__(PyMethod.java:218) ~[?:?]
        at org.python.core.PyMethod.__call__(PyMethod.java:213) ~[?:?]
        at org.python.core.PyObject._jcallexc(PyObject.java:3565) ~[?:?]
        at org.python.core.PyObject._jcall(PyObject.java:3598) ~[?:?]
        at org.python.proxies.core.rules$_FunctionRule$53.execute(Unknown Source) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.shared.simple.SimpleRuleActionHandlerDelegate.execute(SimpleRuleActionHandlerDelegate.java:34) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.internal.delegates.SimpleActionHandlerDelegate.execute(SimpleActionHandlerDelegate.java:59) ~[?:?]
        at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1183) ~[bundleFile:?]
        ... 8 more

I’m not sure how useful those log messages are but I included them anyway! :slight_smile:

That’s not the full exception and that’s missing at least the first line of the error.

It was my fault! Obviously! I hadn’t included this line above the two rules:

from core.log import logging, LOG_PREFIX

Thanks for your help as always!

I’m running OH 3.2m4 and I could NOT get this format to work with having it’s own start/stop tags on it. OH would not create the actual logging file with this format.

I had to use the format OH 3.2m4 was using for start/stop tags to get it to work below.

<PatternLayout Pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n"/>

Best, Jay