History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: LBCORE-47
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Blocker Blocker
Assignee: Ceki Gulcu
Reporter: todd orr
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
logback-core

JMS Appender Fails - Odd Interaction with Commons Logging

Created: 05/Apr/08 01:12 AM   Updated: 17/Oct/08 11:48 PM
Component/s: Appender
Affects Version/s: unspecified
Fix Version/s: None

File Attachments: 1. Zip Archive testbed.zip (5 kb)

Environment:
Operating System: Windows
Platform: PC

Bugzilla Id: http://bugzilla.qos.ch/show_bug.cgi?id=144


 Description  « Hide
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&lt;/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.

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
todd orr - 05/Apr/08 01:15 AM
Created an attachment (id=29)
M2 example project

This eclipse/M2 project will demonstrate the bug described.

Ceki Gulcu - 15/Oct/08 11:03 PM
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.


Ceki Gulcu - 17/Oct/08 11:48 PM
Problem fixed with the release of SLF4J 1.5.4.