Spring Logging SLF4J binded to Log4J

Question

I'm trying to configure my SpringMVC application to log using SLF4J instead of vanilla commons-logging.

I'm totally stuck, my file doesn't log anything although if I debug the code the expression if (log.isDebugEnabled()) { is evaluated to true.

What I'm doing wrong?

This is my config:

My pom.xml

<!-- Logging -->
<dependency>
        <groupId>org.springframework</groupId>
        <artifactId>spring-context</artifactId>
        <version>${org.springframework-version}</version>
        <exclusions>
            <!-- Exclude Commons Logging in favor of SLF4j -->
            <exclusion>
                <groupId>commons-logging</groupId>
                <artifactId>commons-logging</artifactId>
            </exclusion>
        </exclusions>
</dependency>
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jcl-over-slf4j</artifactId>
        <version>${org.slf4j-version}</version>
        <scope>runtime</scope>
</dependency>
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${org.slf4j-version}</version>
</dependency>
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>${org.slf4j-version}</version>
        <scope>runtime</scope>
</dependency>
<dependency>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
        <version>1.2.17</version>
        <scope>runtime</scope>
</dependency>

My log4j.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration PUBLIC "-//APACHE//DTD LOG4J 1.2//EN"       "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

<!-- Appenders -->
<appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%-5p: %c - %m%n" />
    </layout>
</appender>

<appender name="fileAppender" class="org.apache.log4j.FileAppender">
    <param name="Threshold" value="ALL" />
    <param name="File" value="${catalina.home}/logs/workcontrol.log" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d  %-5p  [%c{1}] %m %n" />
    </layout>
</appender>

<!-- Application Loggers -->
<logger name="es.jumtech.workcontrol">
    <level value="ALL" />
    <appender-ref ref="fileAppender" />
</logger>

<!-- 3rdparty Loggers -->
<logger name="org.springframework.core">
    <level value="info" />
</logger>

<logger name="org.springframework.beans">
    <level value="info" />
</logger>

<logger name="org.springframework.context">
    <level value="info" />
</logger>

<logger name="org.springframework.web">
    <level value="info" />
</logger>

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

<!-- Root Logger -->
<root>
    <priority value="ERROR" />
    <appender-ref ref="console" />
</root>

</log4j:configuration>

And my Java Class which should log:

package es.jumtech.workcontrol.persistence.initial;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.ApplicationListener;
import org.springframework.context.event.ContextRefreshedEvent;
import org.springframework.stereotype.Component;
import org.springframework.transaction.annotation.Transactional;

import es.jumtech.workcontrol.persistence.dao.ProfileDAO;
import es.jumtech.workcontrol.persistence.dao.RoleDAO;
import es.jumtech.workcontrol.persistence.entity.Profile;
import es.jumtech.workcontrol.persistence.entity.Role;

@Component
public class DataSeeder implements ApplicationListener<ContextRefreshedEvent> {

@Autowired
private RoleDAO roleDAO;

@Autowired
private ProfileDAO profileDAO;

private static final Logger log = LoggerFactory.getLogger(DataSeeder.class);

@Override
@Transactional(readOnly = false)
public void onApplicationEvent(ContextRefreshedEvent event) {
    // Se inicializan los roles
    loadRoles();

    // Se inicializan los perfiles
    loadProfiles();
}

private void loadRoles() {
    if (log.isDebugEnabled()) {
        log.debug("Se comprueba si existen los roles");
    }

    Role roleBoss = roleDAO.getRoleByName(Role.BOSS);
    if (roleBoss == null) {
        log.error("No existe el rol ROLE_BOSS, se crea");
        roleBoss = new Role();
        roleBoss.setRole(Role.BOSS);
        roleDAO.createRole(roleBoss);
    }

    Role roleAdmin = roleDAO.getRoleByName(Role.ADMIN);
    if (roleAdmin == null) {
        log.error("No existe el rol ROLE_ADMIN, se crea");
        roleAdmin = new Role();
        roleAdmin.setRole(Role.ADMIN);
        roleDAO.createRole(roleAdmin);
    }

    Role roleWorker = roleDAO.getRoleByName(Role.WORKER);
    if (roleWorker == null) {
        log.error("No existe el rol ROLE_WORKER, se crea");
        roleWorker = new Role();
        roleWorker.setRole(Role.WORKER);
        roleDAO.createRole(roleWorker);
    }
}

private void loadProfiles() {
    log.error("Se comprueba si existen los perfiles");

    Profile deliveryProfile = profileDAO.getProfileByName("Repartidor");
    if (deliveryProfile == null) {
        log.error("No existe el perfil Repartidor, se crea");
        deliveryProfile = new Profile();
        deliveryProfile.setProfile("Repartidor");
        profileDAO.createProfile(deliveryProfile);
    }

    Profile comercialProfile = profileDAO
            .getProfileByName("Agente Comercial");
    if (comercialProfile == null) {
        log.error("No existe el perfil Agente Comercial, se crea");
        comercialProfile = new Profile();
        comercialProfile.setProfile("Agente Comercial");
        profileDAO.createProfile(comercialProfile);
    }

    Profile officeProfile = profileDAO.getProfileByName("Oficinista");
    if (officeProfile == null) {
        log.error("No existe el perfil Oficinista, se crea");
        officeProfile = new Profile();
        officeProfile.setProfile("Oficinista");
        profileDAO.createProfile(officeProfile);
    }

}
}

SOLUTION

    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-data-solr</artifactId>
        <version>1.1.4.RELEASE</version>
    </dependency>

As @mp911de pointed, this dependency was importing the Logback library which also implements SLFJ4, and the logger that was returning:

private static final Logger log = LoggerFactory.getLogger(DataSeeder.class);

Was instance of ch.qos.logback.classic.Logger instead of org.slf4j.impl.Log4jLoggerAdapter

Thanks in advance, Diego.

Answer 1

Did you check for any SLF4J output? In case multiple bindings for SLF4J are present, SLF4J complains about it.

The other issue is; you've set your logger category es.jumtech.workcontrol to level ALL which causes isDebugEnabled() to return true. You should see at least something in there (in case you logged more than 8k, which is the default buffer size).

I propose three things:

1. set the root logger temporarily to ALL or DEBUG
2. Start your application with -Dlog4j.debug=true. You should see some details of bootstrapping log4j.
3. Make sure, that logger.getClass().getName() is org.slf4j.impl.Log4jLoggerAdapter

HTH, Mark

Answer 2

This is the set up I usually go for. Works without problem in my maven projects.

Maven dependencies:

<!-- The slf4j api -->
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${org.slf4j-version}</version>
</dependency>
<!-- The slf4j implementation -->
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>${org.slf4j-version}</version>
        <scope>runtime</scope>
</dependency>

log4j.properties - this file should be located in your src/main/resources directory:

# Root logger logging level option
log4j.rootLogger=ERROR, appenderName

# Redirect log messages to a log file
log4j.appender.appenderName=org.apache.log4j.RollingFileAppender
#outputs to Tomcat home
log4j.appender.appenderName.File=${catalina.home}/logs/MyLog.log
log4j.appender.appenderName.MaxFileSize=5MB
log4j.appender.appenderName.MaxBackupIndex=10
log4j.appender.appenderName.layout=org.apache.log4j.PatternLayout
log4j.appender.appenderName.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

Create the log in your java code:

private static final Logger LOG = LoggerFactory.getLogger(MyClass.class);

And of course, invoke the log:

LOG.error("Some exception happened", exception);