java - logback with EJB3.1

Question

I am using logback/slf4j to handle logging in my application. Everything was working perfectly until I started using EJBs. Once I added a stateless EJB to my app, the logger started ignoring my logback.xml and stopped using my appenders. I switched to a programmatic logger configuration to see what was wrong and now I am getting the following error when I try to use my logger within the EJB:

org.slf4j.impl.JDK14LoggerFactory cannot be cast to ch.qos.logback.classic.LoggerContext

stemming from the line:

LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();

Is there any special configuration necessary to get logback to work with EJBs? If it matters I am deploying on glassfish v3.

Answer 1

This looks very close to the problem described in this thread and I suspect a similar class loading issue. Because of the way logback loads logback.xml (more precisely the way it retrieves a ClassLoader to do so), it may fail at picking up its configuration file and fall back on a default BasicConfiguration.

Not sure how you package your code but the suggested workaround is to include the logback.xml in a EAR lib. If you aren't using an EAR packaging, try to identify the class loader used to see where to put the logback.xml file.

At the end, this might be a problem in logback. Didn't check their issue tracker though.

Update: If you use a war packaging, try to configure GlassFish to use firstly the child classloaders before to delegate. In the sun-web.xml:

<sun-web-app>
  <class-loader delegate="false"/>
</sun-web-app>

---

Update: I did a little test on my side and... I cannot reproduce your problem. I've created a project for a Java EE 6 webapp which has the following structure:

$ tree sample
sample
|-- pom.xml
`-- src
    `-- main
        |-- java
        |   `-- com
        |       `-- stackoverflow
        |           `-- q2418355
        |               |-- SimpleEJB.java
        |               `-- SimpleServlet.java
        |-- resources
        |   `-- logback.xml
        `-- webapp
            |-- META-INF
            |   `-- MANIFEST.MF
            |-- WEB-INF
            |   `-- lib
            `-- index.jsp

My pom.xml looks like:

<?xml version="1.0" encoding="UTF-8"?>
<project xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd"
  xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <modelVersion>4.0.0</modelVersion>
  <groupId>com.stackoverflow.q2418355</groupId>
  <artifactId>sample</artifactId>
  <version>1.0-SNAPSHOT</version>
  <packaging>war</packaging>
  <name>sample Maven Webapp</name>
  <url>http://maven.apache.org</url>
  <dependencies>
    <dependency>
      <groupId>javax</groupId>
      <artifactId>javaee-api</artifactId>
      <version>6.0</version>
      <scope>provided</scope>
    </dependency>
    <dependency>
      <groupId>junit</groupId>
      <artifactId>junit</artifactId>
      <version>4.7</version>
      <scope>test</scope>
    </dependency>
    <dependency>
      <groupId>ch.qos.logback</groupId>
      <artifactId>logback-classic</artifactId>
      <version>0.9.18</version>
    </dependency>
    <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-api</artifactId>
      <version>1.5.11</version>
    </dependency>
  </dependencies>
  <build>
    <plugins>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>2.0.2</version>
        <configuration>
          <source>1.6</source>
          <target>1.6</target>
        </configuration>
      </plugin>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-war-plugin</artifactId>
        <version>2.1-beta-1</version>
        <configuration>
          <failOnMissingWebXml>false</failOnMissingWebXml>
        </configuration>
      </plugin>
    </plugins>
    <finalName>sample</finalName>
  </build>
</project>

The code for SimpleEJB.java is:

package com.stackoverflow.q2418355;

import javax.ejb.Stateless;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Stateless
public class SimpleEJB {
    private static Logger logger = LoggerFactory.getLogger(SimpleEJB.class);

    public String sayHello(String name) {
        logger.debug(">> sayHello()");
        logger.debug("<< sayHello()");
        return "Hello " + name + "!!!";
    }
}

The code for SimpleServlet.java is:

package com.stackoverflow.q2418355;

import java.io.IOException;
import java.io.PrintWriter;

import javax.ejb.EJB;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@WebServlet(urlPatterns = { "/SimpleServlet" })
public class SimpleServlet extends HttpServlet {
    @EJB
    SimpleEJB bean;

    private static Logger logger = LoggerFactory.getLogger(SimpleServlet.class);

    @Override
    public void doGet(HttpServletRequest request, HttpServletResponse response) throws IOException {
        logger.debug(">> doGet()");
        PrintWriter out = response.getWriter();
        out.println("<html><body>");
        out.println("<h2>Serving at: " + request.getContextPath() + "</h2>");
        out.println("<h2>Invoking EJB: " + bean.sayHello("Duke") + "</h2>");
        out.println("</body></html>");
        logger.debug("<< doGet()");
    }
}

The code for index.jsp is:

<html>
<body>
<h2>Hello World!</h2>
Invoke the Servlet by clicking <a href="SimpleServlet">here</a>.
</body>
</html>

And my logback.xml looks like:

<configuration>
  <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="FILE" class="ch.qos.logback.core.FileAppender">
    <File>/tmp/logs/testFile.log</File>
    <Append>true</Append>

    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern>
    </layout>
  </appender>

  <logger name="com.stackoverflow.q2418355" level="TRACE"/>

  <root level="debug">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
  </root>
</configuration>

My logback.xml gets propertly loaded and I get the following trace (taken from my log file) when invoking the servlet:

10913 [http-thread-pool-8080-(1)] DEBUG com.stackoverflow.q2418355.SimpleServlet - >> doGet()
10928 [http-thread-pool-8080-(1)] DEBUG com.stackoverflow.q2418355.SimpleEJB - >> sayHello()
10928 [http-thread-pool-8080-(1)] DEBUG com.stackoverflow.q2418355.SimpleEJB - << sayHello()
10932 [http-thread-pool-8080-(1)] DEBUG com.stackoverflow.q2418355.SimpleServlet - << doGet()

I did also try with the EJB packaged in its own JAR and deployed in WEB-INF/lib and get the same result, it just works. Can you spot any obvious difference? Maybe upload a simplified version of your app (will very likely be required for the bug report BTW).

I am running GlassFish v3 under Eclipse 3.5 (with the GlassFish v3 plugin).