Logging in openHAB 3

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.

3 Likes

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>
2 Likes

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

1 Like

Does anybody know how to add regex filter to this new XML file?

Same question here. Did you already find out @Kamil_Matuszczak?

Yes, but now I’m not at computer.
Remind me tomorrow:)

See:

1 Like

Do we still have te reboot to apply the changes in the XML file? It’s very unconvenient for me, because in OH3 that breaks the LogTail and the GoogleTTS voice, so with every change I have to reinstall (unable to do that for GoogleTTS) them…

Hope this will be fixed :slight_smile:

Did anyone try to set monitorInterval in log4j2.xml:

<Configuration monitorInterval="30">

This should check the file every 30 seconds for changes and apply them.
Maybe there is one restart necessary after you added it initially.

2 Likes

Will try it when my OH3 is up and running again. Having some SATA > USB3.0 convertor troubles at the moment… waiting for shipment :wink:

I can confirm that this is working for me. :clap: :clap:

Awesome. I think this would be worthwhile to submit for inclusion in the core, but maybe backing off the interval a little bit. Seems to me that one minute or even five minutes would be sufficient for seeing your changes relatively quickly.