logback

JMS Appender Fails - Odd Interaction with Commons Logging

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Blocker Blocker
  • Resolution: Fixed
  • Affects Version/s: None
  • Fix Version/s: None
  • Component/s: logback-core
  • Labels:
    None
  • Environment:

    Operating System: Windows
    Platform: PC

  • Bugzilla Id:
    144

Description

I'm not sure exactly what's going on, but I've been able to determine that the JMS appender doesn't work under certain circumstances due to some interaction with commons logging.

Here is my maven POM:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>foo.bar</groupId>
<artifactId>testbed</artifactId>
<name>Testbed</name>
<packaging>jar</packaging>
<version>0.1-SNAPSHOT</version>
<build>
<plugins>
<plugin>
<artifactId>maven-compiler-plugin</artifactId>
<configuration>
<source>1.5</source>
<target>1.5</target>
</configuration>
</plugin>
</plugins>
</build>
<dependencies>
<dependency>
<groupId>org.apache.activemq</groupId>
<artifactId>activemq-core</artifactId>
<version>5.0.0</version>
<exclusions>
<exclusion>
<groupId>commons-logging</groupId>
<artifactId>commons-logging</artifactId>
</exclusion>
<exclusion>
<groupId>commons-logging</groupId>
<artifactId>commons-logging-api</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.4.3</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl104-over-slf4j</artifactId>
<version>1.4.3</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
<version>0.9.9</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>0.9.9</version>
</dependency>
</dependencies>
</project>

Here is my logback config:

<configuration debug="true">

<appender name="STDOUT"
class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>
%d

{HH:mm:ss.SSS}

[%thread] %-5level %logger

{36}

- %msg%n
</Pattern>
</layout>
</appender>

<!--
<appender name="QUEUE"
class="ch.qos.logback.classic.net.JMSQueueAppender">
<InitialContextFactoryName>
org.apache.activemq.jndi.ActiveMQInitialContextFactory
</InitialContextFactoryName>
<ProviderURL>tcp://localhost:61616</ProviderURL>
<QueueConnectionFactoryBindingName>
ConnectionFactory
</QueueConnectionFactoryBindingName>
<QueueBindingName>dynamicQueues/queue.foo.logger</QueueBindingName>
</appender>

<logger name="foo.bar.testbed">
<level value="DEBUG" />
<appender-ref ref="QUEUE" />
</logger>
-->
<root>
<level value="TRACE" />
<appender-ref ref="STDOUT" />
</root>

</configuration>

Uncommenting the QUEUE appender results in the following stack trace:

Failed to instantiate [ch.qos.logback.classic.LoggerContext]
Reported exception:
java.lang.ExceptionInInitializerError
at org.apache.activemq.ActiveMQConnectionFactory.<init>(ActiveMQConnectionFactory.java:88)
at org.apache.activemq.ActiveMQConnectionFactory.<init>(ActiveMQConnectionFactory.java:121)
at org.apache.activemq.ActiveMQConnectionFactory.<init>(ActiveMQConnectionFactory.java:117)
at org.apache.activemq.jndi.ActiveMQInitialContextFactory.createConnectionFactory(ActiveMQInitialContextFactory.java:201)
at org.apache.activemq.jndi.ActiveMQInitialContextFactory.createConnectionFactory(ActiveMQInitialContextFactory.java:140)
at org.apache.activemq.jndi.ActiveMQInitialContextFactory.getInitialContext(ActiveMQInitialContextFactory.java:65)
at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:247)
at javax.naming.InitialContext.init(InitialContext.java:223)
at javax.naming.InitialContext.<init>(InitialContext.java:197)
at ch.qos.logback.core.net.JMSAppenderBase.buildJNDIContext(JMSAppenderBase.java:49)
at ch.qos.logback.classic.net.JMSQueueAppender.start(JMSQueueAppender.java:89)
at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:89)
at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:310)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:173)
at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:154)
at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:48)
at ch.qos.logback.core.joran.spi.Interpreter.play(Interpreter.java:336)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:96)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:74)
at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:38)
at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:23)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:34)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:43)
at org.slf4j.impl.StaticLoggerBinder.initialize(StaticLoggerBinder.java:62)
at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:53)
at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:48)
at org.slf4j.LoggerFactory.<clinit>(LoggerFactory.java:60)
at foo.bar.testbed.LoggerTester.main(LoggerTester.java:9)
Caused by: java.lang.IllegalStateException: Logging factory implementation cannot be null. See also http://www.slf4j.org/codes.html#null_LF
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:86)
at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)
at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:131)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:204)
at org.apache.activemq.ActiveMQPrefetchPolicy.<clinit>(ActiveMQPrefetchPolicy.java:30)
... 29 more
Failed to instantiate logger [ch.qos.logback.classic.selector.ContextSelector]
Reported exception:
java.lang.IllegalStateException: contextSelector cannot be null. See also http://logback.qos.ch/codes.html#null_CS
at org.slf4j.impl.StaticLoggerBinder.getLoggerFactory(StaticLoggerBinder.java:98)
at org.slf4j.LoggerFactory.<clinit>(LoggerFactory.java:60)
at foo.bar.testbed.LoggerTester.main(LoggerTester.java:9)
Exception in thread "main" java.lang.IllegalStateException: Logging factory implementation cannot be null. See also http://www.slf4j.org/codes.html#null_LF
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:101)
at foo.bar.testbed.LoggerTester.main(LoggerTester.java:9)

However, removing the SLF4J commons bridge and un-excluding the commons libs from activemq results in the correct behavior. At this point the commons logging is not running through SLF4J at this point. So this is not desirable.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
todd orr added a comment -

Created an attachment (id=29)
M2 example project

This eclipse/M2 project will demonstrate the bug described.

Show
todd orr added a comment - Created an attachment (id=29) M2 example project This eclipse/M2 project will demonstrate the bug described.
Hide
Permalink
Ceki Gulcu added a comment -

Todd,

Thank you for supplying a testbed. It made it easier to reproduce the problem.

The problem can be described as follows:

1) In the static initializer of the LoggerFactory class, the result of
StaticLoggerBinder.SINGLETON.getLoggerFactory() is assigned to the
loggerFactory variable

2) the StaticLoggerBinder.SINGLETON.getLoggerFactory() call,
instantiates a logback LoggerContext which proceeds with
auto-initialization.

3) auto-initialization reads the config file which creates a .ActiveMQInitialContextFactory

4) this ActiveMQInitialContextFactory class performs logging via
commons-logging. However, at this stage the loggerFactory variable is
not yet assigned. Hence the error.

There are several ways to solve this problem.

A) assign loggerFactory to a nopFactory value just before calling
StaticLoggerBinder.SINGLETON.getLoggerFactory()

B) have LoggerFactory invoke auto-initialization as a second step
after the loggerFactory variable is assigned. This would require the
addition of a new method, say autoInitialize()w to the ILoggerFactory
interface.

C) Have logback perform auto-initialization in two steps. In the first
step only non-re-entrant appenders are configured. Re-entrant
appenders are left as a job to be performed by a different thread a
later time. This is too complicated a solution to be further
discussed.

Approach A implies that a NOPLogger needs to be merged into slf4j-api.
Approach B would work very well with logback. However, this bug is not
logback specific, if log4j were the underlying logging system, then it
would still occur. Given that log4j is not a native SLF4J
implementation without knowledge of the
ILoggerFactory.autoInitialize() method, approach B is not valid for
log4j.

I guess that just leaves A.

Show
Ceki Gulcu added a comment - Todd, Thank you for supplying a testbed. It made it easier to reproduce the problem. The problem can be described as follows: 1) In the static initializer of the LoggerFactory class, the result of StaticLoggerBinder.SINGLETON.getLoggerFactory() is assigned to the loggerFactory variable 2) the StaticLoggerBinder.SINGLETON.getLoggerFactory() call, instantiates a logback LoggerContext which proceeds with auto-initialization. 3) auto-initialization reads the config file which creates a .ActiveMQInitialContextFactory 4) this ActiveMQInitialContextFactory class performs logging via commons-logging. However, at this stage the loggerFactory variable is not yet assigned. Hence the error. There are several ways to solve this problem. A) assign loggerFactory to a nopFactory value just before calling StaticLoggerBinder.SINGLETON.getLoggerFactory() B) have LoggerFactory invoke auto-initialization as a second step after the loggerFactory variable is assigned. This would require the addition of a new method, say autoInitialize()w to the ILoggerFactory interface. C) Have logback perform auto-initialization in two steps. In the first step only non-re-entrant appenders are configured. Re-entrant appenders are left as a job to be performed by a different thread a later time. This is too complicated a solution to be further discussed. Approach A implies that a NOPLogger needs to be merged into slf4j-api. Approach B would work very well with logback. However, this bug is not logback specific, if log4j were the underlying logging system, then it would still occur. Given that log4j is not a native SLF4J implementation without knowledge of the ILoggerFactory.autoInitialize() method, approach B is not valid for log4j. I guess that just leaves A.
Hide
Permalink
Ceki Gulcu added a comment -

Problem fixed with the release of SLF4J 1.5.4.

Show
Ceki Gulcu added a comment - Problem fixed with the release of SLF4J 1.5.4.

People

  • Assignee:
    Ceki Gulcu
    Reporter:
    todd orr
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: