Taming openHAB 2 Logging

[Dim (Angelos)]

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)]

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]

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]

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

[automatic (Allen)]

I am trying to get my Zwave logging working again after updating to 2.2.0. Tried implementing the suggestions in this thread and sample config from @Dim. The appender creates the ZWave.log file, but it stays empty. Can anyone point me in the right direction as to what the problem may be?

# Common pattern layout for appenders
#log4j2.pattern = %d{ISO8601} | %-5p | %-16t | %-32c{1} | %X{bundle.id} - %X{bundle.name} - %X{bundle.version} | %m%n

# Root logger
log4j2.rootLogger.level = WARN
log4j2.rootLogger.appenderRefs = out, osgi
log4j2.rootLogger.appenderRef.out.ref = LOGFILE
log4j2.rootLogger.appenderRef.osgi.ref = OSGI

# Karaf Shell logger
log4j2.logger.shell.name = org.apache.karaf.shell.support
log4j2.logger.shell.level = OFF
log4j2.logger.shell.appenderRefs = stdout
log4j2.logger.shell.appenderRef.stdout.ref = STDOUT

# Security audit logger
log4j2.logger.audit.name = org.apache.karaf.jaas.modules.audit
log4j2.logger.audit.level = INFO
log4j2.logger.audit.additivity = false
log4j2.logger.audit.appenderRefs = audit
log4j2.logger.audit.appenderRef.audit.ref = AUDIT

# openHAB specific logger configuration

log4j2.logger.openhab.name = org.openhab
log4j2.logger.openhab.level = INFO
# log4j2.logger.openhab.level = DEBUG

log4j2.logger.smarthome.name = org.eclipse.smarthome
log4j2.logger.smarthome.level = INFO
# log4j2.logger.smarthome.level = DEBUG

log4j2.logger.smarthomeItemStateEvent.name = smarthome.event.ItemStateEvent
log4j2.logger.smarthomeItemStateEvent.level = ERROR
log4j2.logger.smarthomeItemAddedEvent.name = smarthome.event.ItemAddedEvent
log4j2.logger.smarthomeItemAddedEvent.level = ERROR
log4j2.logger.smarthomeItemRemovedEvent.name = smarthome.event.ItemRemovedEvent
log4j2.logger.smarthomeItemRemovedEvent.level = ERROR
log4j2.logger.smarthomeThingStatusInfoEvent.name = smarthome.event.ThingStatusInfoEvent
log4j2.logger.smarthomeThingStatusInfoEvent.level = ERROR
log4j2.logger.smarthomeThingAddedEvent.name = smarthome.event.ThingAddedEvent
log4j2.logger.smarthomeThingAddedEvent.level = ERROR
log4j2.logger.smarthomeThingRemovedEvent.name = smarthome.event.ThingRemovedEvent
log4j2.logger.smarthomeThingRemovedEvent.level = ERROR
log4j2.logger.smarthomeInboxUpdatedEvent.name = smarthome.event.InboxUpdatedEvent
log4j2.logger.smarthomeInboxUpdatedEvent.level = ERROR

log4j2.logger.events.name = smarthome.event
log4j2.logger.events.level = INFO
log4j2.logger.events.additivity = false
log4j2.logger.events.appenderRefs = event
log4j2.logger.events.appenderRef.event.ref = EVENT
log4j2.logger.events.appenderRef.osgi.ref = OSGI

log4j2.logger.jupnp.name = org.jupnp
log4j2.logger.jupnp.level = ERROR

log4j2.logger.jmdns.name = javax.jmdns
log4j2.logger.jmdns.level = ERROR

#log4j2.logger.org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper = ERROR
#log4j2.logger.org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper = ERROR
#log4j2.logger.org.apache.karaf.kar.internal.KarServiceImpl = ERROR

# Appenders configuration

# Console appender not used by default (see log4j2.rootLogger.appenderRefs)
log4j2.appender.console.type = Console
log4j2.appender.console.name = STDOUT
log4j2.appender.console.layout.type = PatternLayout
log4j2.appender.console.layout.pattern = %d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n

# Rolling file appender
log4j2.appender.out.type = RollingRandomAccessFile
log4j2.appender.out.name = LOGFILE
log4j2.appender.out.fileName = /var/log/openhab2/openhab.log
log4j2.appender.out.filePattern = /var/log/openhab2/openhab.log.%i
log4j2.appender.out.immediateFlush = true
log4j2.appender.out.append = true
log4j2.appender.out.layout.type = PatternLayout
log4j2.appender.out.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j2.appender.out.policies.type = Policies
log4j2.appender.out.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.out.policies.size.size = 16MB

# Event log appender
log4j2.appender.event.type = RollingRandomAccessFile
log4j2.appender.event.name = EVENT
log4j2.appender.event.fileName = /var/log/openhab2/events.log
log4j2.appender.event.filePattern = /var/log/openhab2/events.log.%i
log4j2.appender.event.immediateFlush = true
log4j2.appender.event.append = true
log4j2.appender.event.layout.type = PatternLayout
log4j2.appender.event.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c] - %m%n
log4j2.appender.event.policies.type = Policies
log4j2.appender.event.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.event.policies.size.size = 16MB

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

# OSGi appender
log4j2.appender.osgi.type = PaxOsgi
log4j2.appender.osgi.name = OSGI
log4j2.appender.osgi.filter = *
log4j2.logger.org_openhab_binding_zwave.level = DEBUG
log4j2.logger.org_openhab_binding_zwave.name = org.openhab.binding.zwave

### Custom Loggers ###
# 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

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

[sihui]

Compare it to my working example above:

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.logg…