logback with EJB3.1

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 programm开发者_运维问答atic 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.

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).

The org.slf4j.impl.JDK14LoggerFactory cannot be cast to ch.qos.logback.classic.LoggerContext exception shows that SLF4J is not bound to logback-classic but to slf4j-jdk14. In short, logback code is not to blame because it is not being exercised nor called.

It looks like GFv3 is exporting slf4j-jdk14.jar into your application and thus overriding your choice of the logging back-end, logback in this case. This is one of those scenarios where the app server inadvertently imposes its choices on the user.

If indeed GFv3 imposes it's SLF4J binding on the end-user, then that's a GFv3 issue which must be solved by GFv3 developers. I might be wrong but I think they assume that the end-user will not want any other logging functionality beyond what is provided by java.util.logging and just bundle slf4j-jdk14 in GFv3. Users needs to contact them and complain that their assumption is incorrect. It is also possible that they are aware of this issue and already provide a workaround...

Here is pretty much the exact relevant code:

The Login EJB:

@Stateless 
@Interceptors(LoggingInterceptor.class)
public class LoginEJB
{
    @PersistenceContext(unitName = "persistence")
    private EntityManager em;

    public User getUser(String username)
    {
        try
        {
            Query query = em.createQuery("Select u from User u where u.userName = '" + username + "'");
            User user = (User) query.getSingleResult();
            return user;
        } catch (NoResultException e)
        {
            return null;
        }

    }
}

The interceptor where my logging code is:

import javax.interceptor.AroundInvoke;
import javax.interceptor.InvocationContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;


public class LoggingInterceptor
{
    private Logger logger = LoggerFactory.getLogger(this.getClass());

    @AroundInvoke
    public Object logMethod(InvocationContext ic) throws Exception
    {

        logger.info("[{}] Entering - {}()", ic.getTarget().toString() , ic.getMethod().getName());
        try
        {
            return ic.proceed();
        } finally
        {
           logger.info("[{}] Exiting - {}()", ic.getTarget().toString() , ic.getMethod().getName());
        }
    }
}

The logback.xml

<configuration scan="true">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS} [%-5level] [%logger{36}] - %msg%n</Pattern>
        </layout>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>c:\ItamLogs\log.txt</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>c:\ItamLogs\Archive\log-%d{yyyy-MM-dd}.txt</FileNamePattern>
        </rollingPolicy>

        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>[%-5level] - %d{HH:mm:ss.SSS} [%logger{35}] - %msg%n</Pattern>
        </layout>
    </appender>

    <logger name="org.hibernate">
        <level value="WARN"/>
    </logger>

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

The jsf2.0 backing bean.

@ManagedBean
public class LoginBacking extends AbstractBacking
{
    @NotEmpty(message = "User Name required.")
    private String username;
    @NotEmpty(message = "Password required.")
    private String password;
    @EJB
    private LoginEJB loginEJB;

    public String getPassword()
    {
        return password;
    }

    public void setPassword(String password)
    {
        this.password = password;
    }

    public String getUsername()
    {
        return username;
    }

    public void setUsername(String username)
    {
        this.username = username;
    }

    public String performLogin()
    {
        String result = "login";
        User user = loginEJB.getUser(username);

        if(null == user || !user.getPassword().equals(password))
        {
            this.getFacesContext().addMessage("login-form:button-submit", new FacesMessage("The User Name or Password entered is incorrect."));
            return result;
        }

        this.setCurrentUser(user);
        result = "success";
        return result;
    }
}

I have a jsf page that has

<span id="submit-button">
  <h:commandButton id="button-submit" value="Sign On" action="#{loginBacking.performLogin}" />
</span>

finally my pom

<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/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>


    <groupId>com.test</groupId>
    <artifactId>tester</artifactId>
    <version>1.0/version>

    <name>Code</name>

    <packaging>war</packaging>


    <repositories>
        <repository>
            <id>maven2-repository.dev.java.net</id>
            <name>Java.net Repository for Maven</name>
            <url>http://download.java.net/maven/2/</url>
        </repository>
        <repository>
            <snapshots />
            <id>codecaus</id>
            <name>codehaus</name>
            <url>http://repository.codehaus.org</url>
        </repository>
        <repository>
            <snapshots />
            <id>ibiblio</id>
            <url>http://www.ibiblio.org/maven2/</url>
        </repository>
        <repository>
            <id>jboss</id>
            <url>http://repository.jboss.com/maven2</url>
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>false</enabled>
            </snapshots>
        </repository>
        <repository>
            <id>jboss-snapshot</id>
            <url>http://snapshots.jboss.org/maven2</url>
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>true</enabled>
            </snapshots>
        </repository>
        <repository>
            <id>java.net.glassfish</id>
            <name>Repository hosting the jee6 artifacts</name>
            <url>http://download.java.net/maven/glassfish</url>
        </repository>
    </repositories>
    <pluginRepositories>
        <pluginRepository>
            <id>jboss-plugins</id>
            <url>http://repository.jboss.com/maven2</url>
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>false</enabled>
            </snapshots>
        </pluginRepository>
        <pluginRepository>
            <id>jboss-snapshot-plugins</id>
            <url>http://snapshots.jboss.org/maven2</url>
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>true</enabled>
            </snapshots>
        </pluginRepository>
    </pluginRepositories>

    <dependencies>
        <dependency>
            <groupId>javax.faces</groupId>
            <artifactId>jsf-api</artifactId>
            <version>2.0</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>javax.servlet</groupId>
            <artifactId>servlet-api</artifactId>
            <version>2.5</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>javax.el</groupId>
            <artifactId>el-api</artifactId>
            <version>1.0</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>javax.validation</groupId>
            <artifactId>validation-api</artifactId>
            <version>1.0.0.GA</version>
        </dependency>
        <dependency>
            <groupId>org.glassfish</groupId>
            <artifactId>bean-validator</artifactId>
            <version>3.0-JBoss-4.0.0.Beta3</version>
        </dependency>

        <dependency>
            <groupId>org.glassfish.extras</groupId>
            <artifactId>glassfish-embedded-all</artifactId>
            <version>3.0</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>javax</groupId>
            <artifactId>javaee-api</artifactId>
            <version>6.0-SNAPSHOT</version>
        </dependency>

        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.7</version>
        </dependency>


        <dependency>
            <groupId>javax.faces</groupId>
            <artifactId>jsf-api</artifactId>
            <version>2.0</version>
            <scope>provided</scope>
        </dependency>

        <!-- JPA -->

        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-core</artifactId>
            <version>3.5.0-CR-2</version>
        </dependency>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-annotations</artifactId>
            <version>3.5.0-CR-2</version>
        </dependency>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-commons-annotations</artifactId>
            <version>3.2.0.Beta1</version>
        </dependency>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-entitymanager</artifactId>
            <version>3.5.0-CR-2</version>
        </dependency>
        <dependency>
            <groupId>org.hibernate</groupId>
            <artifactId>hibernate-c3p0</artifactId>
            <version>3.5.0-CR-2</version>
        </dependency>

        <dependency>
            <groupId>postgresql</groupId>
            <artifactId>postgresql</artifactId>
            <version>8.4-701.jdbc4</version>
        </dependency>


        <!-- logging -->
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-core</artifactId>
            <version>0.9.18</version>
        </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>

        <dependency>
            <groupId>org.eclipse.persistence</groupId>
            <artifactId>javax.persistence</artifactId>
            <version>2.0.0</version>
        </dependency>
    </dependencies>
    <properties>
        <netbeans.hint.deploy.server>gfv3ee6</netbeans.hint.deploy.server>
    </properties>

    <build>
        <pluginManagement>
            <plugins>
                <plugin>
                    <groupId>org.apache.maven.plugins</groupId>
                    <artifactId>maven-compiler-plugin</artifactId>
                    <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.0</version>
                </plugin>

            </plugins>
        </pluginManagement>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-war-plugin</artifactId>
                <version>2.0</version>
            </plugin>
        </plugins>
    </build>
</project>

Edit: I also tried changing my logger to a static, no change.

Basically the problem is that the application server usesprovides slf4j AND that your attempts to use it goes to the application server slf4j binding instead of the one you want yourself.

Can't you just use the slf4j binding in Glassfish?