Questions about logging in OpenHAB2

I’m currently setting up openHAB 2. In order to find the cause for my problems, I tried to turn on DEBUG logging.
I know about the log:set command, but it doesn’t seem to have effects directly.
For example to get TRACEs of all milight communication I set this:

log:set TRACE org.openhab.binding.milight2

But nothing changes in the logs although I’m communicating to my milight bulbs. Is there any commit necessary in order for the setting to get active?

The second question is about the logging pattern. For some for me not understandable reason it’s common use to setup the logging in a way that the fully qualified package name is trimmed after n characters. This way it’s not possible for me to set some “spamming” packages - e.g. jetty - to a higher log level than the others because I don’t know the complete package name.
Is there a way to set a custom logging pattern?

See the following posting to get you started.

With a little bit of research into log4j you can configure the logs hire ever you want.

When you issue commands like log:set in the console, it only affects the logs that you can tail from within the console and do not affect those written to file.

Take heed of the warning. Right now the log config gets replaced on an upgrade so keep a copy of your changes before updating until that gets fixed.

Great - got it. Thanks rlkoshak!

Sorry - I’m not completely successful :wink: After setting DEBUG to the root logger I see Debug Messages in openhab.log, but still not from the milight binding. According to the milight binding’s code a debug message is logged on every command it sends.

Could there be some special things to do - e.g. related to OSGI?

This is the log4j configuration:

# Root logger
log4j.rootLogger = DEBUG, 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.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.openhab.binding.milight2 = DEBUG
log4j.logger.org.eclipse.jetty = WARN
log4j.logger.org.ops4j.pax.web.service.jetty = WARN

# 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] [%c] - %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

Follow the same approach as I showed to put the zwave logs into a separate file, only use milight binding package.

I’ll put a link to the official documentation here for reference: http://docs.openhab.org/administration/logging.html

@peez increasing the log level for a binding can be done by log:set and checked with log:list in the karaf console. This setting will be lost after a restart of openHAB. Could you try another binding to rule out a general problem and maybe pin it on milight…?

openhab> log:list
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | WARN
javax.jmdns                                                 | ERROR
org.eclipse.smarthome                                       | INFO
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR

openhab> log:set DEBUG org.openhab.binding.astro

openhab> log:list
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | WARN
javax.jmdns                                                 | ERROR
org.eclipse.smarthome                                       | INFO
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.openhab.binding.astro                                   | DEBUG
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR

After a few minutes, on log:tail:

23:39:21.404 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro PositionalJob for thing astro:moon:home
23:39:21.415 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Moon for thing astro:moon:home
23:40:39.546 [DEBUG] [g.astro.internal.job.AbstractBaseJob] - Starting astro PositionalJob for thing astro:sun:home
23:40:39.548 [DEBUG] [ding.astro.handler.AstroThingHandler] - Publishing planet Sun for thing astro:sun:home

That’s actually a pretty good point. Maybe this should be proposed as an improvement! Did you find a solution?

It is this line in org.ops4j.pax.logging.cfg

log4j.appender.out.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n

I think, if I remember correctly, if you replace the %-36.36c with %C it will print out the fully qualified classname un-truncated. Beware, the apache docs indicate this is expensive and could slow you down, so change it back once you are done debugging you problem.

Exactly. You should care about upper- and lower case. Depending on how the logging is done this might be a slight difference.
https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html

Is it possible to turn off logging (in org.ops4j.pax.logging.cfg) for specific bindings, like, the HTTP 1.x Binding, or the EXEC Binding?
When the device is offline, it should not print an error.

See the following: