Taming openHAB 2 Logging

Tags: #<Tag:0x00007f2fb0d5fc28> #<Tag:0x00007f2fb0d5fac0>

This post is OBE. See Log4j2 Sample Config

**NOTE: With the build from November 10 #579 the location of all the files in runtime/karaf/etc have moved to userdata/etc. The instructions below have been updated accordingly. If you are running an older verison of openHAB (anything older than build #579), the location of the file is runtime/karaf/etc.

As almost everyone is aware, openHAB 2 uses a completely different logging library and approach to logging than openHAB 1.x does, replacing logback with log4j.

This means a completely new way of configuring the logger to split out the logs from different bindings to their own file, for example. But this can still be done.

As I mentioned, openHAB 2 uses log4j 2.x (I’m not sure of the exact version) and instead of using XML or JSON for configuring the loggers, openHAB 2 uses a traditional properties file. This file is located at:

userdata/etc/org.ops4j.pax.logging.cfg

Log4j uses pretty much the same concepts as logback does: loggers and appenders.

The logger specifies the namespace that the logger applies to, the level to log at, which appenders to log to, and whether or not the logger is additive. There is a parent child relationship with loggers with the logger for org.openhab being the parent to org.openhab.binding.zwave. If additivity is set to true the log sent to the child logger also get sent to the parent logger. So if you don’t want to see the zwave binding’s logs in openhab.log, set additivity to false.

The appender specifies where (e.g. which file) and the format of the logging statements. One appender can be used for multiple loggers.

So, if you wanted to split out the zwave log into its own file and set its level to TRACE you would define the logger:

# zwave logger
log4j.logger.org.openhab.binding.zwave = TRACE, zwave, osgi:*
log4j.additivity.org.openhab.binding.zwave = false

and define the appender

# File appender - zwave.log
log4j.appender.zwave=org.apache.log4j.RollingFileAppender
log4j.appender.zwave.layout=org.apache.log4j.PatternLayout
log4j.appender.zwave.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c{1}] - %m%n
log4j.appender.zwave.file=${openhab.logdir}/zwave.log
log4j.appender.zwave.append=true
log4j.appender.zwave.maxFileSize=10MB
log4j.appender.zwave.maxBackupIndex=10

And you are good to go. The secret sauce is the comma separated set of parameters on the logger definition line TRACE, zwave, osgi:*. The first item sets the logging level to TRACE. The second two parameters define the appenders that logger logs to. In this case it is our zwave appender (the name of the appender is the word after .appender) and the OSGI console if you are someone who watches logs through the Karaf console.

To turn off the events.log file all you need to do is remove the appender event from the log4j.logger.smarthome.event = INFO, event, osgi:* line.

WARNING: the official openHAB 2 docs on logging warns:

Currently the file org.ops4j.pax.logging.cfg will get overwritten with the default version on every update of openHAB. There is an issue on this.

So backup your file and remember to reapply it after you run an update.

20 Likes

EDIT: No longer necessary with builds > #579

I thought I’d post here because I’ve recently set my logging configuration up to a desired setting and have saved myself some time with the following. Instead of manually editing the file each time I update, I add any new binding specific configuration lines in a separate file, e.g. extra-logging.cfg and append this file to the logging.cfg with the following bash script. For configuration changes I’m using sed e.g.:

#!/bin/bash

LOG_DIR="/usr/share/openhab2/runtime/karaf/etc/org.ops4j.pax.logging.cfg"

sudo cat extra-logging.cfg >> $LOG_DIR
sudo sed -i -e 's/log4j.logger.smarthome.event = INFO/log4j.logger.smarthome.event = WARN/g' $LOG_DIR

This means that I just have to run the bash script after each apt-get upgrade, and I can keep using this script safely even if there are additions to the original logging config:

sudo apt-get update && sudo apt-get upgrade && sudo bash post-openhab-update.sh
3 Likes

Hi rich,
Thank you for sharing your understanding with us.

It seems does NOT work for me.
I hope I can control logging in Eclipse IDE console, like
$log:set
in Karaf console.

As I use Eclipse IDE, I edit
log4j.logger.org.eclipse.smarthome = ERROR (originally DEBUG)
in
/home/xiaomin/java-neon/git/openhab-distro/distributions/distribution-resources/src/main/resources/etc/org.ops4j.pax.loggin.cfg

But it seems all DEBUG message still show.

1 Should I do some compilation to make it take effect or do some more configuration?
2 Or it simply works only for Karaf console, not working on Eclipse IDE console and telnet osgi console($telnet localhost 5555).

Thank you very much.

I have no experience with running OH in Eclipse. You should not have to recompile to make it work though. It’s just a config file loaded by log4j when OH starts.

Beyond that I’m no help. I can only address running OH on its own.

Thank you very much for reply and clarification.

1 logback_debug.xml works for Eclipse IDE.
2 Also, org.ops4j.pax.logging.cfg works by OH2 on my board.

Thank you for your info.

Updated to point at the new location of the config file since build #579.

can someone help me please with taming logs from systeminfo binding?
Maybe I am asking something pretty obvious/noob but I want to remove these from the log

2017-07-12 22:36:08.612 [ItemStateChangedEvent ] - HAserver_Sensors_CPUTemperature changed from 57.0 to 56.5
2017-07-12 22:36:08.618 [ItemStateChangedEvent ] - HAserver_Cpu_Load changed from 6.6 to 1.3
2017-07-12 22:36:08.621 [ItemStateChangedEvent ] - HAserver_Memory_Used changed from 40.4 to 40.5
2017-07-12 22:36:12.612 [ItemStateChangedEvent ] - HAserver_Sensors_CPUTemperature changed from 56.5 to 57.0
2017-07-12 22:36:12.619 [ItemStateChangedEvent ] - HAserver_Cpu_Load changed from 1.3 to 0.8
2017-07-12 22:36:16.617 [ItemStateChangedEvent ] - HAserver_Cpu_Load changed from 0.8 to 2.9
2017-07-12 22:36:20.613 [ItemStateChangedEvent ] - HAserver_Sensors_CPUTemperature changed from 57.0 to 56.5

I tryed editing org.ops4j.pax.logging.cfg file by adding this line

log4j.logger.org.openhab.binding.systeminfo = WARN

and after restart nothing changed in the log files, entries are kicking in every 2sec (as they are supposed to do).

How to remove/change log level for this binding? Somewhere on the forum I read that using Karaf will make changes permanently, but according to docs page, it has to be done via file (docs is quite brief about how to change config file) http://docs.openhab.org/administration/logging.html#config-file

Thanks!

Follow the example above and create both a logger and an appender. This will put the logs into a separate file.

To change the logging level you need provide the level AND the appenders it uses. So you would need:

log4j.logger.org.openhab.binding.systeminfo = WARN, out, osgi:*

That will change the logging level of the systeminfo binding but continue to send them to the out appender which is what writes to openhab.log.

Hm, tried something similar to get rid of ItemStateChangedEvent from astro and ntp binding with no luck

log4j.logger.org.eclipse.smarthome.binding.ntp = WARN, out, osgi:*
log4j.additivity.org.eclipse.smarthome.binding.ntp = false

Defining loggers for the bindings does nothing to the events. By using smarthome.event.ItemStateChangedEvent I can change the log level of all events including the ones I like to tame.

That is correct. The Events logging statements are generated by the Event Bus and by default logged using the event logger.

After some reading I found a solution to filter out ItemStateChangedEvent’s from my event log:

# File appender - events.log
...
log4j.appender.event.filter.ntp=org.apache.log4j.varia.StringMatchFilter
log4j.appender.event.filter.ntp.StringToMatch=ntp_ntp_local
log4j.appender.event.filter.ntp.AcceptOnMatch=false
log4j.appender.event.filter.moon=org.apache.log4j.varia.StringMatchFilter
log4j.appender.event.filter.moon.StringToMatch=astro_moon_local
log4j.appender.event.filter.moon.AcceptOnMatch=false
log4j.appender.event.filter.sun=org.apache.log4j.varia.StringMatchFilter
log4j.appender.event.filter.sun.StringToMatch=astro_sun_local
log4j.appender.event.filter.sun.AcceptOnMatch=false

# Sift appender
...
2 Likes

Thank you @rlkoshak and @ptweety , I manage to use your example @ptweety and removed some logs that I dont think are that interesting, allowing me to focus on the relevant stuff. I guess dedicated logger is the “correct” approach, but for a begynner it helps to have a “easier” total overview. This is what I used to remove cpu load event that was being logged every 2sec

log4j.appender.event.filter.sysinfocpuload=org.apache.log4j.varia.StringMatchFilter
log4j.appender.event.filter.sysinfocpuload.StringToMatch=HAserver_Cpu_Load
log4j.appender.event.filter.sysinfocpuload.AcceptOnMatch=false

Maybe my requirement is a little different, but I didn’t find a solution so far:
I’d like to have a second log file like openhab.log (named openhab.warn), but restricted to log entries of severity WARN or higher.
The classic openhab.log should not be affected by this addition.

So I could watch the openhab.warn log and send new entries once per hour per mail to myself, so I’m noted, if something unusual happens.

My only problem is, that I didn’t find out to implement this. If I configure an additional logger/appender like the default one, this always implies, that the debug/info output disappears from openhab.log, too :frowning:

Maybe someone has an idea how to implement this.

Greetings
Roland

1 Like

OH2 LOGGING ROLLOVER QUESTIONS-
In searching the Community, I find conflicting information, probably because some of it applies to OH1, and some of it applies to OH2. So I have the following questions regarding log rollover in OH2:

  • It appears that OH2 does NOT use any of the conventional Debian/Ubuntu logging facilities, so the traditional methods I have used to manage log sizes and rollover frequency do not apply. Is this correct?
  • In the community I see frequent references to a file called logback.xml. This file is NOT present in OH2. Is this correct?
  • In its default configuration, OH2 creates two log files. On a Debian system, these are /var/log/openhab2/events.log and /var/log/openhab2/openhab.log. Is this correct? (FWIW, I cannot remember if I specifically configured my system to write these logs or if it was provided by default.)
  • In its default configuration, OH2’s log files will grow indefinitely, eventually causing the host to run out of disk space and crash. Is this correct?
  • Is there a simple, straightforward tutorial out in the community somewhere that can be applied to a default OH2 installation with sane log rotation assumptions that will prevent systems from eventually crashing with full disks?

Thanks!

1 Like

Even though OH2 does not use rsyslog, you can still use logrotate on the /var/log/openhab2/ files. (optional, since rotation happens anyway… see maxFileSize & maxBackupIndex below)
Most of the log options (like max size, etc) can be configured using $OPENHAB_USERDATA/etc/org.ops4j.pax.logging.cfg
More info here: https://karaf.apache.org/manual/latest/#_log

Correct.
logback.xml = OH1
org.ops4j.pax.logging.cfg = OH2

Correct (provided by default)

Not correct. Defaults (for both): maxFileSize=10MB with maxBackupIndex=10

http://docs.openhab.org/administration/logging.html

Ps: Log4j v2 support is coming soon :open_mouth:

Ps2: My custom log config with 2 extra log file appenders. 1 for KNX and 1 for Z-Wave:
# Root logger
log4j.rootLogger = INFO, out, osgi:*
log4j.throwableRenderer=org.apache.log4j.OsgiThrowableRenderer

# openHAB specific logger configuration
log4j.logger.smarthome.event = INFO, event, osgi:*
log4j.logger.smarthome.event.ItemStateEvent = WARN
log4j.logger.com.beowulfe.hap.HomekitRoot = WARN
log4j.logger.com.beowulfe.hap = WARN
log4j.logger.smarthome.event.ItemAddedEvent = WARN
log4j.logger.smarthome.event.ItemRemovedEvent = WARN
log4j.logger.smarthome.event.ThingStatusInfoEvent = WARN
log4j.logger.smarthome.event.InboxUpdatedEvent = WARN
log4j.additivity.smarthome.event = false

log4j.logger.org.openhab = INFO
log4j.logger.org.eclipse.smarthome = INFO
log4j.logger.org.jupnp = ERROR
log4j.logger.javax.jmdns = ERROR
log4j.logger.org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper = WARN
log4j.logger.org.apache.karaf.kar.internal.KarServiceImpl = ERROR
log4j.logger.org.apache.aries.spifly = ERROR
# log4j.logger.org.openhab.binding.zwave = ERROR

### Custom Loggers ###
# ZWave
log4j.logger.org.openhab.binding.zwave = INFO, ZWave, osgi:*
log4j.additivity.org.openhab.binding.zwave = false
# KNX
log4j.logger.org.openhab.binding.knx = INFO, KNX, osgi:*
log4j.additivity.org.openhab.binding.knx = false

### Custom Appenders ###
# ZWave
log4j.appender.ZWave=org.apache.log4j.RollingFileAppender
log4j.appender.ZWave.layout=org.apache.log4j.PatternLayout
log4j.appender.ZWave.layout.ConversionPattern=%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.ZWave.file=${openhab.logdir}/ZWave.log
log4j.appender.ZWave.append=true
log4j.appender.ZWave.maxFileSize=10MB
log4j.appender.ZWave.maxBackupIndex=10
# KNX
log4j.appender.KNX=org.apache.log4j.RollingFileAppender
log4j.appender.KNX.layout=org.apache.log4j.PatternLayout
log4j.appender.KNX.layout.ConversionPattern=%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.KNX.file=${openhab.logdir}/KNX.log
log4j.appender.KNX.append=true
log4j.appender.KNX.maxFileSize=10MB
log4j.appender.KNX.maxBackupIndex=10

# CONSOLE appender not used by default
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n

# File appender - openhab.log
log4j.appender.out=org.apache.log4j.RollingFileAppender
log4j.appender.out.layout=org.apache.log4j.PatternLayout
log4j.appender.out.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.out.file=${openhab.logdir}/openhab.log
log4j.appender.out.append=true
log4j.appender.out.maxFileSize=10MB
log4j.appender.out.maxBackupIndex=10

# File appender - events.log
log4j.appender.event=org.apache.log4j.RollingFileAppender
log4j.appender.event.layout=org.apache.log4j.PatternLayout
log4j.appender.event.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c{1}] - %m%n
log4j.appender.event.file=${openhab.logdir}/events.log
log4j.appender.event.append=true
log4j.appender.event.maxFileSize=10MB
log4j.appender.event.maxBackupIndex=10

# Sift appender
log4j.appender.sift=org.apache.log4j.sift.MDCSiftingAppender
log4j.appender.sift.key=bundle.name
log4j.appender.sift.default=openhab
log4j.appender.sift.appender=org.apache.log4j.FileAppender
log4j.appender.sift.appender.layout=org.apache.log4j.PatternLayout
log4j.appender.sift.appender.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.sift.appender.file=${openhab.logdir}/$\\{bundle.name\\}.log
log4j.appender.sift.appender.append=true
log4j.logger.org.openhab.action.mail = WARN
log4j.logger.org.openhab.binding.astro = WARN
log4j.logger.org.openhab.binding.mpower = WARN
log4j.logger.org.openhab.binding.mqtt = WARN
log4j.logger.org.openhab.binding.ntp = WARN
log4j.logger.org.openhab.binding.unifi = WARN
log4j.logger.org.openhab.binding.weather = WARN
log4j.logger.org.openhab.binding.wol = INFO
log4j.logger.org.openhab.persistence.mapdb = WARN
log4j.logger.org.openhab.binding.samsungtv = WARN
log4j.logger.org.openhab.io.homekit = WARN
log4j.logger.org.openhab.io.transport.mqtt = WARN
log4j.logger.tuwien.auto.calimero = WARN
log4j.logger.org.openhab.persistence.influxdb = WARN
log4j.logger.org.openhab.ui.paperui = WARN
log4j.logger.org.openhab.ui = WARN
log4j.logger.smarthome = INFO
log4j.logger.smarthome.ui.paper = WARN
log4j.logger.smarthome.binding.astro = WARN
log4j.logger.smarthome.event.ItemStateChangedEvent = WARN
log4j.logger.smarthome.event.GroupItemStateChangedEvent = WARN
log4j.logger.smarthome.event.ThingStatusInfoChangedEvent = WARN
log4j.logger.smarthome.event.ItemCommandEvent = INFO
log4j.logger.smarthome.event.ThingAddedEvent = WARN
log4j.logger.smarthome.event.ItemChannelLinkAddedEvent = WARN
log4j.logger.smarthome.event.InboxRemovedEvent = WARN
log4j.logger.smarthome.event.ExtensionEvent = WARN
log4j.logger.smarthome.event.ConfigStatusInfoEvent = WARN
log4j.logger.smarthome.event.ChannelTriggeredEvent = WARN
log4j.logger.smarthome.event.ThingUpdatedEvent = WARN
log4j.logger.smarthome.event.ThingRemovedEvent = WARN
log4j.logger.smarthome.event.ItemChannelLinkRemovedEvent = WARN
log4j.logger.smarthome.event.InboxAddedEvent = WARN
log4j.logger.smarthome.transform.regex = INFO
log4j.logger.smarthome.transform.map = INFO
log4j.logger.org.apache.sshd = WARN
log4j.logger.org.apache.karaf = WARN
log4j.logger.org.quartz.core.QuartzScheduler = WARN
log4j.logger.org.quartz.core = INFO
log4j.logger.internal.service.FeaturesServiceImpl = WARN
log4j.logger.io.netty.handler.logging.LoggingHandler = WARN
log4j.logger.org.quartz.simpl = WARN
log4j.logger.org.quartz.impl = WARN
log4j.logger.org.ops4j.pax.web = WARN
log4j.logger.org.eclipse.jetty.util.log = WARN
log4j.logger.org.eclipse.jetty.server = WARN
log4j.logger.org.jupnp.transport.spi.StreamClient = ERROR
log4j.logger.BindingEvent = INFO
log4j.logger.smarthome.event.BindingEvent = INFO
log4j.logger.org.openhab.ui.iconset.climacons = TRACE
1 Like

This was also true for OH 1.x, for what it is worth.

As Dim said, the default logging configuration will prevent this out of the box.

1 Like

@Dim, thank you for your very clear answers. This is a great help.

@rlkoshak, thanks also for your additional clarifications.

Not sure how to mark this resolved - I saw a post somewhere else where that mark was added. In any case, all of my questions are answered, and very quickly as well. I appreciate your responsiveness.

I would like to suggest that the information in this posting be added to the documentation page below.

If no one objects, I will make a submission along with a PR sometime after mid-August.

1 Like

Well, in this case because you responded to an existing thread rather than starting a new thread you don’t have that option. Neither answer is the solution to the original posting.

When you do start a new thread, you will have a little box with a checkmark below each response. You can press that for the solution to the problem in the original posting.

Given the changes that are in progress with logging (upgrading to Log4J 2) and the userdata folder (moving more stuff out), it might be better to wait. Though I know for a certainty any PR would be gladly accepted.

I’d like to extend the question regarding logging to remote logging. I already found out that the following addition to org.ops4j.pax.logging.cfg makes openhab log to a remote syslog host:

# Syslog appender
log4j.appender.syslog=org.apache.log4j.net.SyslogAppender
log4j.appender.syslog.layout=org.apache.log4j.PatternLayout
log4j.appender.syslog.layout.ConversionPattern=openhab2: %d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.syslog.syslogHost=<SyslogHost>
log4J.appender.syslog.facility=KARAF
log4j.appender.syslog.facilityPrinting=false

“syslog” has to be added to the log4j.rootlogger line to activate it.

The problem with this is that all multiline log lines (like tracebacks) are cut after the first \n.

Is there a solution for this? Will Log4J 2 bring any improvements in this department?