Taming openHAB 2 Logging

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:

automatic · October 28, 2017, 11:37am

I did. The only difference I can see (for Zwave) is:
Logger: you have INFO and I have DEBUG
Appender: We have different paths because mine installation is apt based

Or am I completely blind?

bjsjr · October 28, 2017, 3:10pm

Just a guess on my part but I think the problem may be the # OSGi appender section just above your ### Custom Loggers ### section. I think that section was added if you set your zwave binding to debug in Karaf and may be overriding your custom appender. Once again, this is just a guess.

I added @sihui zwave code to the end of my cfg and everything works fine. I also changed the level to DEBUG and the DEBUG info started showing up in my zwave.log file. I do not have a OSGi appender section in my config though, nor did I ever change to DEBUG in Karaf.

Just a thought.

automatic · October 28, 2017, 3:49pm

Brilliant guess, Bill I was about to just copy Dim’s full config and get done with it. Though I was wondering about that additional zwave logger in the osgi section too. Then I saw your post and commented out that logger. Problem solved, thanks!

jpwise · January 1, 2018, 12:16am

Just adding this here since I couldn’t find it again after doing it almost a year ago, and the OH2.2 upgrade reverted the /srv/openhab2-userdata/etc/org.ops4j.pax.logging.cfg file.

Simple string filtering on the event log. Useful for filtering out high change items that don’t need constant log visibility.

Prior to OH2.2 - using log4j

# Jp - filter out stuff
log4j.appender.event.filter.smappee=org.apache.log4j.varia.StringMatchFilter
log4j.appender.event.filter.smappee.StringToMatch=power_smappee
log4j.appender.event.filter.smappee.AcceptOnMatch=false

Taken from an example in Log4j2 Sample Config, the following appears to do the same under OH2.2

# Jp - filter out stuff
log4j2.appender.event.filter.regex.type = RegexFilter
log4j2.appender.event.filter.regex.regex = .*power_smappee.*
log4j2.appender.event.filter.regex.onMatch = DENY
log4j2.appender.event.filter.regex.onMisMatch = ACCEPT

There are probably better ways to do it, but for now that works, and excludes the power_smappee (power consumption, changes by the second) from the log files.

Thx.
Jp.

rlkoshak · January 3, 2018, 4:05pm

It would be great if you post this as its own thread in Examples and Tutorials. Lots of people have asked for how to filter out events from events.log.

jpwise · January 5, 2018, 7:34am

Took your advice and split it out into it’s own post. Since I had such a hard time finding the information originally (and after updating with OH2.2 replacing the config file) I don’t doubt you’re right it’s something a lot of people ask for.

New topic is at : OpenHAB - Filtering event logs

It’s pretty straightforward as configuration goes, and hopefully adding the filtering reference to the topic name should help people find it readily enough.

Thx.
Jp.

rbausdorf · January 5, 2018, 8:43am

Side hint: If you change you logging conf and the change does not seem to work, check if the lines you changed have trailing whitespaces ! It took me several hours to figure that out - so I like to save that time to you …

andirs · January 7, 2018, 1:08pm

log4j also seems to privide a CronTriggeringPolicy in order to rotate the log. For example rotating at midnight.

Did someone already manage to implement that? I tried but failed because all examples found in the internet use xml and not this openhabs approach.

Spaceman_Spiff · January 7, 2018, 3:10pm

I was asking something similar here:

Unfortunately official documentation is for the xml file which was discontinued with OH2.
I am not sure why and nobody answered me. Maybe beacuse things would be too easy, then!

dude0001 · January 8, 2018, 2:41pm

Do these instructions still apply to the current release? Is there anything different if running on Windows as a Windows Service?

rlkoshak · January 8, 2018, 3:07pm

The OP is out of date. See some of the later posts in the thread or Log4j2 Sample Config.

There is nothing different with the configs when running on Windows.

Spaceman_Spiff · January 9, 2018, 5:57am

What exactly do you mean?

rlkoshak · January 9, 2018, 4:34pm

The log4j config file is identical when running on all platforms. One does not need to do anything special to make logging work when running on Windows as a service.

NathanNotNate · January 15, 2018, 2:51am

I totally broke all openhab logging after I edited the org.ops4j.pax.logging.cfg file. Now nothing is logging at all. I replaced the text of the file with what I found in the org.ops4j.pax.logging.cfg.dpkg-old file but no luck.

I’ve restarted it several times, used the openhabian config tool to install openhabian 2.2 (I believe I was running 2.3 snapshot) because I was under the impression that would reset everything in /var/lib/openhab2 and there for fix it but still no luck.

here is the file as it sits now

# Root logger
log4j.rootLogger = WARN, out, osgi:*
log4j.throwableRenderer=org.apache.log4j.OsgiThrowableRenderer

# openHAB specific logger configuration
log4j.logger.smarthome.event = INFO, event, osgi:*
log4j.logger.smarthome.event.ItemStateEvent = ERROR
log4j.logger.smarthome.event.ItemAddedEvent = ERROR
log4j.logger.smarthome.event.ItemRemovedEvent = ERROR
log4j.logger.smarthome.event.ThingStatusInfoEvent = ERROR
log4j.logger.smarthome.event.InboxUpdatedEvent = ERROR
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 = ERROR
log4j.logger.org.apache.karaf.kar.internal.KarServiceImpl = ERROR
log4j.logger.org.apache.aries.spifly = ERROR

# 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

Anyone have any pointers?

sihui · January 15, 2018, 7:55am

That is not the content of the original file. Grab it from here and copy it to your file.

NathanNotNate · January 15, 2018, 4:41pm

Sure enough, that did it. I could have sworn I tried that in my attempts to fix it. Thanks.

Spaceman_Spiff · January 19, 2018, 12:34pm

Does anyone have any Idea how to get TimeBasedTriggering working?

rlkoshak · January 19, 2018, 3:54pm

I replied with my ideas on your original thread. I must have missed it when you first posted.