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

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

Answer 2

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?

Answer 3

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"&gt;
    <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/&lt;/url&gt;
        </repository>
        <repository>
            <snapshots />
            <id>codecaus</id>
            <name>codehaus</name>
            <url>http://repository.codehaus.org&lt;/url&gt;
        </repository>
        <repository>
            <snapshots />
            <id>ibiblio</id>
            <url>http://www.ibiblio.org/maven2/&lt;/url&gt;
        </repository>
        <repository>
            <id>jboss</id>
            <url>http://repository.jboss.com/maven2&lt;/url&gt;
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>false</enabled>
            </snapshots>
        </repository>
        <repository>
            <id>jboss-snapshot</id>
            <url>http://snapshots.jboss.org/maven2&lt;/url&gt;
            <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&lt;/url&gt;
        </repository>
    </repositories>
    <pluginRepositories>
        <pluginRepository>
            <id>jboss-plugins</id>
            <url>http://repository.jboss.com/maven2&lt;/url&gt;
            <releases>
                <enabled>true</enabled>
            </releases>
            <snapshots>
                <enabled>false</enabled>
            </snapshots>
        </pluginRepository>
        <pluginRepository>
            <id>jboss-snapshot-plugins</id>
            <url>http://snapshots.jboss.org/maven2&lt;/url&gt;
            <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.