Taming openHAB 2 Logging

[ThomDietrich]

While we are at it, I’ve posted aa solution on how to send the logs to a Logstash/Elasticsearch server here:

Logging to Logstash+Elasticsearch+Kibana

A few weeks ago I looked into piping my openHAB logs to Elasticsearch via logstash. I found the solution to work reliably but realized that the combination wasn’t as interesting to me as I thought. Steps to take: Install Logstash, Elasticsearch and Kibana Configure a “log4j” input for Logstash Add he following logging setting to the openHAB log file /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg:log4j.rootLogger = WARN,out,tcp,osgi:* # add tcp here # # TCP appender - Logstash+Elasticsearch+K…

[bgilmer (Brad Gilmer)]

@Dim, thanks for very specific information about maxFileSize and maxBackupIndex. Where are these variables set? Also, maxFileSize is clear. Is maxBackupIndex the maximum number of backup files kept? Once the maxBackupIndex number is reached, the oldest file is deleted? Just collecting information for a contribution to the documentation.

@otherCommenters, all good information, and probably need a single article collecting all the information here and other places about logging overall. That said, I think it is important to add a section about default logging rollover policy in the installation documentation so sysadmins such as myself don’t freak out worrying about systems falling over in the middle of the night because of full disks. I am still on vacation, but I hope to put together a short contribution when I get back.

[Dim (Angelos)]

@bgilmer

1. Where are these variables set?
2. Also, maxFileSize is clear. Is maxBackupIndex the maximum number of backup files kept?
3. Once the maxBackupIndex number is reached, the oldest file is deleted?
4. Just collecting information for a contribution to the documentation.

1. /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg
2. Yes
3. Yes
4. Bravo ! (keep in mind that soon, openHAB2 will be upgraded to use Karaf 4.1.x with log4j2)

[PR#484]
Karaf 4.1 now uses log4j2 instead of log4j - which is in general good news. The bad news is that the syntax of userdata/etc/org.ops4j.pax.logging.cfg has changed. As users might have customized that file, we do not overwrite it in our update script. What is your suggestion how we should deal with it?

https://logging.apache.org/log4j/2.x/manual/migration.html

[Dim (Angelos)]

New log4j2 example here: Log4j2 Sample Config

20-200% performance improvement with the new RollingRandomAccessFileAppender !

Source: https://logging.apache.org/log4j/2.0/performance.html#whichAppender

[ralle (Ralph Borchers)]

@Dim

keep in mind that soon, openHAB2 will be upgraded to use Karaf 4.1.x with log4j2

Speaking of Karaf 4.1.x and the new log4j2: with my old 2.2 snapshot that was around #995ish i could filter log output on the console like this

log:tail | grep -v somestring

After upgrading to #1010 the grep -v part of the commandline is ignored. Is this a known new feature?

[LastSamurai (Oliver)]

I am currently setting up my logging preferences and would like to log detailed (DEBUG level) infos to a file while only displaying INFO level stuff in the console. Is that possible somehow?

I tried something like this:

log4j.logger.org.openhab.binding.mysensors = INFO, osgi:*
log4j.logger.org.openhab.binding.mysensors = DEBUG, mysensors:*

where the mysensors binding is what I want to log and ‘mysensors’ is a file logger I created. I am getting an error message though.

Also what does the :* do? I copied that one from the demo rules.

[martmiwp (Michael)]

Hi All,

looking into “my” configuration of the logging, all entries start with log4j2 instead of log4j?

To make use of these suggestions above, can I just change this, or what’s the story.
Sorry - but I am confused.

BTW: I am using the 2.2 Snapshot

Michael

[ThomDietrich]

As @Dim mentioned above, the latest snapshot now uses the new log4j2. The configuration files are different and you should read the official documentation linked above.

See also:

Log4j2 Sample Config

Here is my setup for the new log4j2 logging package that is included in the latest upgrade of openHAB2 snapshot (2.2.0 Build >#1009) All changes happen in the $OPENHAB_USERDATA/etc/org.ops4j.pax.logging.cfg file (full path in Linux with apt installation: /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg) Notes My OH2 installation is very stable and I don’t add many new stuff so I want my logs to show me only Warnings+. I am running the following addons (in addons.cfg):binding = knx1, zwave, m…

[andirs (Andi)]

Since my problem is related to logging i append it here.
Isn’t it possible to handle the log files with logrotate anymore? I have the following set up:

/etc/logrotate.d/openhab
	
		/var/log/openhab2/openhab.log {
		rotate 6
		daily
		nocompress
		missingok
		copytruncate
		}

problem is the copytruncate. When a logrotate is done the new logfile is as big as the old one (and messed up) and new logs are appended. In notepad++ it looks like this:

How can i solve this? Thanks

P.S.:I am on the latest snapshot.

[rlkoshak (Rich Koshak)]

You do realize that openHAB rotates its own log files right? I’m not sure what would happen if you tried to rotate the log out from under it but I would not expect it to work, as you are seeing. Is there something wrong with letting OH do it for you?

[andirs (Andi)]

Thats right, but i prefer having a logfile for each day instead of a 10mb file. I didn’t find a way to implement that in the OH2 logging system.

It worked before but it seems to have stopped a few days/weeks ago.

[rlkoshak (Rich Koshak)]

Are you on an SD card? If so I’m willing to bet real money your SD card is failing. I discovered I had a failing SD card when logrotate stopped working and my syslog filled up the whole file system.

[andirs (Andi)]

Yes i am on a SDcard. Do you have some advise on how to find out if it is really failing? Maybe a an app that tests the card?

[rlkoshak (Rich Koshak)]

No advice needed. If log rotate worked for awhile and doesn’t anymore your SD card is failing. End of story. Backup what you can NOW. Verify the files are not corrupted (most likely they are not), and switch out to a new SD card.

[jannegpriv (Jan Gustafsson)]

Hi!

Just upgraded to 2.2.0 #1066 and I cannot get separate logging to work with log4j2, I’ve tried to configure separate log files for netatmo and rules by adding the following lines:

### Custom Loggers ###
# Logger - netatmo.log
log4j2.logger.netatmo.name = openhab.binding.netatmo
log4j2.logger.netatmo.level = DEBUG
log4j2.logger.netatmo.additivity = false
log4j2.logger.netatmo.appenderRefs = netatmo
log4j2.logger.netatmo.appenderRef.netatmo.ref = NETATMO

log4j2.logger.rules.name = smarthome.model.script.RULES
log4j2.logger.rules.level = DEBUG
log4j2.logger.rules.additivity = false
log4j2.logger.rules.appenderRefs = rules
log4j2.logger.rules.appenderRef.rules.ref = RULES

# Audit file appender
log4j2.appender.netatmo.type = RollingRandomAccessFile
log4j2.appender.netatmo.name = NETATMO
log4j2.appender.netatmo.fileName = /var/log/openhab2/netatmo.log
log4j2.appender.netatmo.filePattern = /var/log/openhab2/netatmo.log.%i
log4j2.appender.netatmo.append = true
log4j2.appender.netatmo.layout.type = PatternLayout
log4j2.appender.netatmo.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.netatmo.policies.type = Policies
log4j2.appender.netatmo.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.netatmo.policies.size.size = 10MB
log4j2.appender.netatmo.strategy.type = DefaultRolloverStrategy
log4j2.appender.netatmo.strategy.max = 10

log4j2.appender.rules.type = RollingRandomAccessFile
log4j2.appender.rules.name = RULES
log4j2.appender.rules.fileName = /var/log/openhab2/rules.log
log4j2.appender.rules.filePattern = /var/log/openhab2/rules.log.%i
log4j2.appender.rules.append = true
log4j2.appender.rules.layout.type = PatternLayout
log4j2.appender.rules.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.rules.policies.type = Policies
log4j2.appender.rules.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.rules.policies.size.size = 10MB
log4j2.appender.rules.strategy.type = DefaultRolloverStrategy
log4j2.appender.rules.strategy.max = 10

The logfiles are created but remains empty:

-rw-r--r-- 1 openhab openhab        0 Oct 21 23:07 netatmo.log
-rw-r--r-- 1 openhab openhab        0 Oct 21 23:07 rules.log
-rw-r--r-- 1 openhab openhab      214 Oct 22 00:37 audit.log
-rw-r--r-- 1 openhab openhab   330214 Oct 22 01:00 openhab.log
-rw-r--r-- 1 openhab openhab   359114 Oct 22 01:01 events.log

Any clues?

BR,

/Janne

[rlkoshak (Rich Koshak)]

I haven’t upgraded to a log4j2 yet so won’t be able to help.

[sihui]

@jannegpriv

Any clues?

See @Dim’s “Custom Config”: Log4j2 Sample Config

[jannegpriv (Jan Gustafsson)]

Hi!

Thanks for the tip, @Dim’s “Custom Config” was my inspiration, but I must have missed some detail.

BR,

/Janne

[sihui]

@jannegpriv

was my inspiration

Mine too

Here is my example: zwave custom logging and rules logging into an “extra.log” (for example logInfo("EXTRA", "PRESENCE: Somebody is home") )

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


# EXTRA
log4j2.logger.rules.name = org.eclipse.smarthome.model.script.EXTRA
log4j2.logger.rules.level = INFO
log4j2.logger.rules.additivity = false
log4j2.logger.rules.appenderRefs = Extra
log4j2.logger.rules.appenderRef.Extra.ref = EXTRA


### Custom Appenders ###
# ZWave
log4j2.appender.ZWave.name = ZWAVE
log4j2.appender.ZWave.type = RollingRandomAccessFile
log4j2.appender.ZWave.fileName = /opt/openhab2/userdata/logs/zwave.log
log4j2.appender.ZWave.filePattern = /opt/openhab2/userdata/logs/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

# EXTRA
log4j2.appender.Extra.name = EXTRA
log4j2.appender.Extra.type = RollingRandomAccessFile
log4j2.appender.Extra.fileName = /opt/openhab2/userdata/logs/extra.log
log4j2.appender.Extra.filePattern = /opt/openhab2/userdata/logs/extra.log.%i
log4j2.appender.Extra.immediateFlush = true
log4j2.appender.Extra.append = true
log4j2.appender.Extra.layout.type = PatternLayout
log4j2.appender.Extra.layout.pattern = %d{dd-MMM-yyyy HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.Extra.policies.type = Policies
log4j2.appender.Extra.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Extra.policies.size.size = 10MB
log4j2.appender.Extra.strategy.type = DefaultRolloverStrategy
log4j2.appender.Extra.strategy.max = 10

Edit: note that I am using a manual install, not an apt-get, regarding the folder structure

[jannegpriv (Jan Gustafsson)]

Hi!

Thank’s for your example,now it works! I’ve missed the full package path in the line (The leading org. was missing):

log4j2.logger.rules.name = org.eclipse.smarthome.model.script.RULES

BR,

/Janne