Taming openHAB 2 Logging

Dim · August 12, 2017, 4:12am

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

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

Dim · August 15, 2017, 10:48am

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 · August 15, 2017, 10:53am

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 · September 4, 2017, 3:56pm

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 · September 25, 2017, 8:19am

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 · September 25, 2017, 11:32am

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:

andirs · October 9, 2017, 6:39pm

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 · October 9, 2017, 7:12pm

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 · October 9, 2017, 7:21pm

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 · October 9, 2017, 7:34pm

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 · October 9, 2017, 7:38pm

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 · October 9, 2017, 7:40pm

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 · October 21, 2017, 11:06pm

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 · October 22, 2017, 12:58am

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

sihui · October 22, 2017, 6:09am

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

jannegpriv · October 22, 2017, 7:22am

Hi!

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

BR,

/Janne

sihui · October 22, 2017, 7:27am

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 · October 22, 2017, 8:06am

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 · October 28, 2017, 11:29am

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 · October 28, 2017, 11:31am

Compare it to my working example above: