Logging in openHAB 3

Tags: #<Tag:0x00007fe73a13c378> #<Tag:0x00007fe73a13c2b0>

I’ve noticed a couple things about logging in openHAB 3. Can anyone shed some light based on your experience?

  • I see the log4j2 logging config file has changed to use the XML format. In openHAB 2, when you changed the logging config file, the changes would take effect immediately. However, whenever I change the log4j2.xml file, the changes are not applied. Instead, I need to restart openHAB for the changes to take effect. Is this the way it works now, or is there something I’m not understanding.

  • It would be nice to be able to use the xinclude feature to keep my custom logging changes separate from the standard system logging configuration. However, I’ve not been able to get this to work. Does anyone have a working example?

  • Does anyone have a working example of how to configure a dedicated log file for a specific binding (e.g. zwave.log for the zwave binding)?

1 Like

There is a long issue that I even spent a good number of hours trying to solve. I think the final conclusion was and remains that this is only sort of possible. The problem is when you change the logging level and settings in the Karaf console, it actually edits/appends to the logging config. I spent quite some time working on it and didn’t get very far. Unfortunately I can’t find that issue again. IIRC, @rossko57 participated on that issue and took a shot at it too, maybe his memory is better than mine. Of course there were two parts to that issue, one was moving to XML and the other was figuring out how to to the xinclude. It looks like the XML part is solved at least. I can’t find the PR where this was implemented either.

It’s been ages since I’ve done this. But it should be relatively straight forward to convert the .properties to XML. The XML syntax is documented at https://logging.apache.org/log4j/2.x/manual/configuration.html#XML.

I think the following:

# ZWave
log4j2.logger.zwave.name = org.openhab.binding.zwave
log4j2.logger.zwave.level = DEBUG
log4j2.logger.zwave.additivity = false
log4j2.logger.zwave.appenderRefs = ZWAVE
log4j2.logger.zwave.appenderRef.zwave.ref = ZWAVE

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

would convert to something like:

<?xml version="1.0" encoding="UTF-8"?>;
<Configuration>
  <Properties>
    <Property name="name1">value</property>
    <Property name="name2" value="value2"/>
  </Properties>
  <filter  ... />
  <Appenders>
    ...
    <!-- Your custom appender config goes here -->
    <RollingRandomAccessFile name="ZWAVE" fileName="${openhab.logdir}/zwave.log" filePattern="${openhab.logdir}/zwave.log.%i" immediateFlush="true" append="true">
      <PatternLayout>
        <Pattern>%d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - </Pattern>
      </PatternLayout>
      <Policies>
        <SizeBasedTriggeringPolicy size="10 MB"/>
      </Policies>
      <DefaultRolloverStrategy max="10"/>
    </RollingRandomAccessFile>
    <!-- End Custom Appender -->
  </Appenders>
  <Loggers>
    ...
    <!-- Your custom logger config goes here-->
    <Logger name="org.openhab.binding.zwave" level="DEBUG" additivity="false">
      <AppenderRef ref="ZWAVE"/>
    </Logger>
    <!-- End Custom logger -->
    <Root level="level">
      <AppenderRef ref="name"/>
    </Root>
  </Loggers>
</Configuration>

I’ve not tried the above but it should work.

Thanks @rlkoshak.

I think I found (some of) the relevant information.

PR to replace properties file with XML

Issue that discusses splitting system config and custom config

1 Like

Doh! I was looking in the wrong repo. Glad you found them!

A couple changes from what you posted above to make it work…

sys: needs to be prepended to openhab.logdir

<RollingRandomAccessFile fileName="${sys:openhab.logdir}/zwave.log" filePattern="${sys:openhab.logdir}/zwave.log.%i" name="ZWAVE" immediateFlush="true" append="true">

Change order of date and add %m%n

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

Edit: The order of date components is needed to make it work with the zwave log analyzer.

1 Like

I thought that was dopcumenetd in the Z-Wave binding documentation. when Things do not go as Planned.

The format of the logger config in OH 3 has changed from properties to XML. The binding docs only show properties and therefore is no longer applicable in OH 3.

1 Like

Did you ever identify a way to reread the XML file without a restart of OH? Having the same issue.

EDIT: Not the best work around but “touch org.ops4j.pax.logging.cfg” triggers the update without restart. Probably needs a bug to track the xml file and not just the cfg.

EDIT2: https://github.com/openhab/openhab-distro/issues/1187 opened to fix this.

In OH2, when you would add config files for things like zwave above, it would peel those configs out of openhab.log (which was nice when you were waiting for a failure so you weren’t flooding your logs out otherwise). In OH3, it seems to duplicate the log entries in both openhab.log and the new log file. For example, I’m peeling lutron off right now with the following:

            <!-- Lutron file appender -->
            <RollingFile fileName="${sys:openhab.logdir}/lutron.log" filePattern="${sys:openhab.logdir}/lutron.log.%i" name="LUTRON">
                    <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n"/>
                    <Policies>
                            <SizeBasedTriggeringPolicy size="16 MB"/>
                    </Policies>
            </RollingFile>


            <Logger level="TRACE" name="org.openhab.binding.lutron" additivity="false">
                    <AppenderRef ref="LUTRON"/>
            </Logger>

Am I missing something on my config or is this a bug?

I’m not seeing this in my custom logger configurations.

Here’s an example of mine.

In the Appenders section:

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

In the Loggers section:

                <!-- ECOBEE -->
                <Logger additivity="false" level="DEBUG" name="org.openhab.binding.ecobee">
                        <AppenderRef ref="ECOBEE"/>
                </Logger>

I was missing immediateFlush=“true”. That fixed it. Thanks!

1 Like