Exception on startup of pax-logging-logback implementation

Description

I added/activated pax-logging-logback implementation in ServiceMix via change in startup.properties and providing the bundles in the system repository.

Received identical error message on ServiceMix startup (see below). I tried both with version 1.7.2 (pre-installed with log4j implementation) and released 1.7.3 which added karaf support (PAXLOGGING-178)

Changes in startup.properties:

karaf shell output:

Environment

ServiceMix 5.0.0

Activity

Show:
StuartS
September 3, 2014, 12:15 PM

I also had a look at the pax-logging code and the exception you're seeing is thrown when a warning/error status event occurs in logback, but logback has not been configured yet (ie. it's still using the default configuration from configureLogbackDefaults in pax-logging-logback). The default status listener will log the status message and create a dummy exception (to get a stacktrace) if there was no associated exception. This also might explain why I don't see it locally - I change the "etc/org.ops4j.pax.logging.cfg" file to point to a basic logback.xml configuration, which will override the default configuration early on in the boot process.

Was there any message in the console directly before the "java.lang.Exception at..." line? That would help narrow down what's causing the original warning/error status event.

Michael Taeschner
September 5, 2014, 8:07 AM

Hi,

sorry for the late reply. I do indeed see a warning right before the exception which I missed before (because offset to the right):

Is there something wrong with our logback config ?? I attached the current logback.xml

full log output:

Michael Taeschner
September 5, 2014, 8:08 AM

added logback.xml

Michael Taeschner
September 5, 2014, 8:09 AM

I am not proficient with logback I must admit so if the problem is caused by incorrect configuration I am sorry as this was provided by the team as standard config.

StuartS
September 5, 2014, 12:13 PM

Hi Michael, the warning from ReconfigureOnChangeFilter is because you have scan="true" in the configuration element. This tells logback to repeatedly scan the configuration file, but this doesn't work with pax-logging because it passes a stream into JoranConfigurator and not the original file URL. This is why logback is warning automatic reconfiguration is impossible, because it doesn't have the original URL to scan.

If you remove scan="true" then the warning will go away. Also note that you don't currently define the applicationId property in your configuration, so some of your logging will probably end up in a file named "isb-applicationId_IS_UNDEFINED.log".

Finally if you want view logging using Karaf's log command then you should add the following appender:

Here's a minimal logback.xml that's roughly the same as the out-of-the-box Karaf Log4j configuration:

Hope it helps

StuartS
September 5, 2014, 12:26 PM

BTW, I can't see a compelling reason why pax-logging-logback has to use doConfigure(InputStream) over doConfigure(File) because it does have the file to begin with. Passing the file into the JoranConfigurator instead of a stream would likely allow use of the scan="true" reconfiguration option.

I also think the new Exception() call in configureLogbackDefaults should add some message, or maybe it should just be omitted, as at the moment it looks like an internal error in pax-logging - whereas it's actually just providing some extra context to any status warnings / errors that occur before the configuration is in place.

Michael Taeschner
September 5, 2014, 12:50 PM

Hi ,

thanks for pointing out the logback.xml config issues, I added the PaxAppenderDelegate appender and fixed the applicationId parameter using MDC discriminator configuration of the SiftingAppender.

This resolves my issue, I have no exception any longer, the log can be accessed via console, only minor inconvenience is following:

Additionally I like your last comments regarding using file for logback config and the improved exception handling.

One more question: To refresh the logback.xml config would I have to restart the pax-logging-logback bundle or is there another approach ?

Michael Taeschner
September 5, 2014, 12:52 PM

Caused by incorrect logback.xml configuration.

See additional points raised by .

StuartS
September 5, 2014, 12:57 PM

As a workaround touching the etc/org.ops4j.pax.logging.cfg file should trigger a configuration update which would reload the logback.xml

StuartS
September 5, 2014, 1:03 PM

PS. log:get assumes that you're using Log4J because it parses the etc/org.ops4j.pax.logging.cfg for the current log levels rather than query the actual backend so it doesn't currently work with pax-logging-logback. However, log:set does work because pax-logging-logback detects that the configuration sent over from Karaf is an attempt to configure log levels and applies them to the current context.

StuartS
September 12, 2014, 10:01 PM

Re-opening to make the two improvements mentioned in this comment:

  • removed misleading exception trace from configureLogbackDefaults

  • changed logback driven configuration to use supplied file reference

With these changes you can now use the scan="true" setting in logback.xml

Fixed

Assignee

StuartS

Reporter

Michael Taeschner

Fix versions

Labels

Components

Affects versions

Priority

Major
Configure