log4j与logback冲突的解决与思考~ 日志级别还设置的是info,为什么会打印出大量的debug日志呢?
   helloworld    发表于:2019-02-23 10:33:41
  阅读 :241   收藏   编辑

原文:https://www.jianshu.com/p/191a95ad0b89

问题

在项目启动时,发现打印了大量的debug日志,但是src/main/resources下明明有log4j.xml,而且日志级别还设置的是info,为什么会打印出大量的debug日志呢?

分析

使用eclipse的Dependency Hierarchy功能可以对pom.xml中定义的jar依赖进行可视化展示。发现项目中与日志相关的jar包有:

slf4j-api.jar
slf4j-log4j12.jar
log4j.jar
logback-classic.jar
logback-core.jar

那么,猜测原因大概是:由于意外地引入了的logback的jar包,破坏了之前的slf4j + slf4j-log4j12 + log4j 的日志架构,使得日志不再通过 log4j 输出(因而log4j.xml设置的info日志级别也随之失效),而是通过 logback 输出,并且logback 默认输出的是debug级别,因此出现了上述问题。

解决

解决的方法很简单:在pom.xml中通过<exclusions/>排除掉 logback 相关的jar即可。

思考

对于这个小问题,解决起来似乎很简单,但是以下几个问题是值得我们进一步思考的:

基于 slf4j + slf4j-log4j12 + log4j 的日志架构,是如何工作的?
为什么引入了 logback 就会破坏之前的日志架构?
如何避免发生log4j和logback冲突的问题?
面向slf4j的接口API编程的最佳实践是什么?

下面就来尝试回答上面的几个问题。

基于 slf4j + slf4j-log4j12 + log4j 的日志架构,是如何工作的?

为了更好的了解其运行原理,我搭建一个简单的项目。见:https://github.com/wanghui0101/learning-slf4j/tree/master/learning-slf4j-sample

/learning-slf4j-sample/src/main/webapp/WEB-INF/web.xml中只简单配置了一个Servlet,指向personal.wh.learning.slf4j.sample.SampleServlet类。此类的源码为:

package personal.wh.learning.slf4j.sample;

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

import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

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

public class SampleServlet extends HttpServlet {

    private static final long serialVersionUID = -870284320856607145L;
    
    private static final Logger logger = LoggerFactory.getLogger(SampleServlet.class);
    
    @Override
    protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        logger.debug("Hello Slf4j ! - debug");
        logger.info("Hello Slf4j ! - info");
        try (PrintWriter writer = resp.getWriter()) {
            writer.write("ok");
        }
    }
    
}

功能很简单,GET请求这个Servlet的时候,通过slf4j的org.slf4j.Logger加载了log4j,并读取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/'>
    <appender name="STDOUT" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%t] %C{2} (%F:%L) - %m%n" />
        </layout>
    </appender>
    <root>
        <priority value="info" />
        <appender-ref ref="STDOUT" />
    </root>
</log4j:configuration>

由于日志级别为info,因此只打印一句Hello Slf4j ! - info

项目的lib包,与日志相关的有:

slf4j-api-1.7.25.jar
slf4j-log4j12-1.7.25.jar
log4j-1.2.17.jar(通过 slf4j-log4j12-1.7.25.jar 传递依赖引入)

源码分析

接下来,我们通过源码分析一下,slf4j是如何加载log4j,并实现日志打印的呢?

org.slf4j.LoggerFactory.getLogger()

我们从org.slf4j.LoggerFactory#getLogger(Class<?> clazz)开始:

public static Logger getLogger(Class<?> clazz) {
    Logger logger = getLogger(clazz.getName()); // 通过类名获取Logger对象
    if (DETECT_LOGGER_NAME_MISMATCH) {
        Class<?> autoComputedCallingClass = Util.getCallingClass();
        if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {
            Util.report(String.format("Detected logger name mismatch. Given name: \"%s\"; computed name: \"%s\".", 
                logger.getName(), autoComputedCallingClass.getName()));
            Util.report("See " + LOGGER_NAME_MISMATCH_URL + " for an explanation");
        }
    }
    return logger; // 返回Logger对象
}

然后org.slf4j.LoggerFactory#getLogger(String name)

public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory(); // 重点
    return iLoggerFactory.getLogger(name);
}

在查看getILoggerFactory()之前,先看一下org.slf4j.ILoggerFactory接口的定义:

public interface ILoggerFactory {
    public Logger getLogger(String name); // 根据Logger的名字返回Logger对象
}

再看一下org.slf4j.Logger接口的定义(只列出主要方法):

public interface Logger {
    public String getName(); // 返回logger实例的名称
    public void trace(String format, Object... arguments);
    public void debug(String format, Object... arguments);
    public void info(String format, Object... arguments);
    public void warn(String format, Object... arguments);
    public void error(String format, Object... arguments);
    public boolean isTraceEnabled();
    public boolean isDebugEnabled();
    public boolean isInfoEnabled();
    public boolean isWarnEnabled();
    public boolean isErrorEnabled();
}

就是打印各级别的日志,以及判断当前的日志级别。

好,继续查看org.slf4j.LoggerFactory#getILoggerFactory()的源码

public static ILoggerFactory getILoggerFactory() {
    if (INITIALIZATION_STATE == UNINITIALIZED) { // 是否是未初始化状态?注意volatile关键字的使用
        // 同步锁,所有线程互斥,只允许1个线程进行下面的初始化操作
        synchronized (LoggerFactory.class) {
            if (INITIALIZATION_STATE == UNINITIALIZED) { // 双重检查
                INITIALIZATION_STATE = ONGOING_INITIALIZATION; // 设置状态为进行中
                performInitialization(); // 执行初始化
            }
        }
    }
    switch (INITIALIZATION_STATE) { // 判断初始化状态
        case SUCCESSFUL_INITIALIZATION: // 成功初始化
            // 返回StaticLoggerBinder中定义的ILoggerFactory的实现类
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION: // 未找到StaticLoggerBinder类
            // 返回无操作(即所有实现的都是空)的org.slf4j.helpers.NOPLoggerFactor
            return NOP_FALLBACK_FACTORY; 
        case FAILED_INITIALIZATION: // 初始化失败,抛异常
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION: // 仍是进行中的状态
            return SUBST_FACTORY;
    }
    // 如果以上的状态都不是,则抛异常
    throw new IllegalStateException("Unreachable code");
}

核心代码是org.slf4j.LoggerFactory#performInitialization()方法:

private final static void performInitialization() {
    bind(); // 与具体的日志实现绑定
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) { // 如果成功初始化
        versionSanityCheck(); // 对版本兼容性的检查,不再看了
    }
}

继续org.slf4j.LoggerFactory#bind()

private final static void bind() {
    try {
        Set<URL> staticLoggerBinderPathSet = null;
        if (!isAndroid()) { // 我们当前并不是Android环境,会执行if语句块的内容
            // 查找所有StaticLoggerBinder类的路径
            staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
            // 如果找到了多个StaticLoggerBinder类,并且不确定使用哪个时,会打印错误信息
            reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
        }
        // 最关键的一句代码
        // 首先看StaticLoggerBinder类的路径是 org.slf4j.impl.StaticLoggerBinder
        // 注意:它并不在 slf4j-api.jar 中,而是在 slf4j-log4j12.jar 中
        // 即:slf4j-api.jar 中定义的是高层接口,实现与具体日志框架绑定是在 slf4j-[日志框架].jar 中
        // 如果项目中只有 slf4j-api.jar 的话,那么就会因为找不到 StaticLoggerBinder 
        // 而进入到 catch (NoClassDefFoundError ncde) 代码块
        // 此句代码确保了一定要找到StaticLoggerBinder类,并且能够执行getSingleton()方法
        StaticLoggerBinder.getSingleton();
        
        // 找到了StaticLoggerBinder,表示初始化成功
        INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;

        // 向控制台打印实际绑定的日志框架
        reportActualBinding(staticLoggerBinderPathSet);
        
        ......
 
    // 如果找不到StaticLoggerBinder类,会执行以下代码
    } catch (NoClassDefFoundError ncde) {
        String msg = ncde.getMessage();
        if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
            INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
            Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
            Util.report("Defaulting to no-operation (NOP) logger implementation");
            Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
        } else {
            failedBinding(ncde);
            throw ncde;
        }

    // 如果能找StaticLoggerBinder类,但是找不到getSingleton()方法,会执行以下代码
    } catch (java.lang.NoSuchMethodError nsme) {
        String msg = nsme.getMessage();
        if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
            INITIALIZATION_STATE = FAILED_INITIALIZATION;
            Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
            Util.report("Your binding is version 1.5.5 or earlier.");
            Util.report("Upgrade your binding to version 1.6.x.");
        }
        throw nsme;
    } catch (Exception e) { // 其它异常
        failedBinding(e);
        throw new IllegalStateException("Unexpected initialization failure", e);
    }
}

小结一下:此方法的实现就是找org.slf4j.impl.StaticLoggerBinder的过程。接下来关注一下具体的过程。

  1. org.slf4j.LoggerFactory#findPossibleStaticLoggerBinderPathSet()

private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

static Set<URL> findPossibleStaticLoggerBinderPathSet() {
    Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>(); // 注意:是有序的Set
    try {
        /* 
         * 通过ClassLoader加载所有的 org/slf4j/impl/StaticLoggerBinder.class
         */
        ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
        Enumeration<URL> paths;
        if (loggerFactoryClassLoader == null) {
            paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
        } else {
            paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
        }
        while (paths.hasMoreElements()) { // 可能有多个
            URL path = paths.nextElement();
            staticLoggerBinderPathSet.add(path); // 添加到Set中
        }
    } catch (IOException ioe) {
        Util.report("Error getting resources from path", ioe);
    }
    return staticLoggerBinderPathSet; // 返回Set
}

org/slf4j/impl/StaticLoggerBinder.class可能有多个,但是目前这个类只在 slfj4-log4j12.jar 中有1个。

  • org.slf4j.LoggerFactory#reportMultipleBindingAmbiguity(Set<URL>)

private static void reportMultipleBindingAmbiguity(Set<URL> binderPathSet) {
    // 找到的这些StaticLoggerBinder是否是有歧义的?
    if (isAmbiguousStaticLoggerBinderPathSet(binderPathSet)) {
        Util.report("Class path contains multiple SLF4J bindings.");
        for (URL path : binderPathSet) { // 如果找到多个则打印错误信息
            Util.report("Found binding in [" + path + "]");
        }
        // 打印一个网址,用于解释多个绑定的情况:https://www.slf4j.org/codes.html#multiple_bindings
        Util.report("See " + MULTIPLE_BINDINGS_URL + " for an explanation.");
    }
}

private static boolean isAmbiguousStaticLoggerBinderPathSet(Set<URL> binderPathSet) {
    return binderPathSet.size() > 1; // 找到多个StaticLoggerBinder就是有歧义的
}

由于目前只找到1个,所以没有歧义。

  • org.slf4j.LoggerFactory.reportActualBinding(Set<URL>)

private static void reportActualBinding(Set<URL> binderPathSet) {
    // 当有歧义时,打印出实际绑定的那个StaticLoggerBinder
    if (binderPathSet != null && isAmbiguousStaticLoggerBinderPathSet(binderPathSet)) {
        Util.report("Actual binding is of type [" + StaticLoggerBinder.getSingleton().getLoggerFactoryClassStr() + "]");
    }
}


至此,绑定过程我们就分析完了。简而言之,就是:查找并加载StaticLoggerBinder的过程。

org.slf4j.impl.StaticLoggerBinder

接下来,我们看一下 slf4j-log4j12.jar 中的 org.slf4j.impl.StaticLoggerBinder

package org.slf4j.impl;

import org.apache.log4j.Level;
import org.slf4j.ILoggerFactory;
import org.slf4j.LoggerFactory;
import org.slf4j.helpers.Util;
import org.slf4j.spi.LoggerFactoryBinder;

public class StaticLoggerBinder implements LoggerFactoryBinder {

    private static final StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

    public static final StaticLoggerBinder getSingleton() { // 构建单例
        return SINGLETON;
    }

    public static String REQUESTED_API_VERSION = "1.6.99"; // !final

    private static final String loggerFactoryClassStr = Log4jLoggerFactory.class.getName();

    private final ILoggerFactory loggerFactory;

    private StaticLoggerBinder() {
        loggerFactory = new Log4jLoggerFactory(); // 重点
        try {
            @SuppressWarnings("unused")
            Level level = Level.TRACE;
        } catch (NoSuchFieldError nsfe) {
            Util.report("This version of SLF4J requires log4j version 1.2.12 or later. See also http://www.slf4j.org/codes.html#log4j_version");
        }
    }

    @Override
    public ILoggerFactory getLoggerFactory() {
        return loggerFactory; // 返回 Log4jLoggerFactory 对象
    }

    @Override
    public String getLoggerFactoryClassStr() {
        return loggerFactoryClassStr;
    }
}

接下来,我们来看org.slf4j.impl.Log4jLoggerFactory的源码(有删减)

package org.slf4j.impl;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;

import org.apache.log4j.LogManager;
import org.slf4j.ILoggerFactory;
import org.slf4j.Logger;

// 实现了 slf4j-api.jar 中的 ILoggerFactory  接口
public class Log4jLoggerFactory implements ILoggerFactory {

    // key - logger的名字
    // value - org.slf4j.Logger接口的实现类,是个适配器 org.slf4j.impl.Log4jLoggerAdapter
     // 考虑并发的情况,使用了 ConcurrentMap
    ConcurrentMap<String, Logger> loggerMap;

    public Log4jLoggerFactory() {
        loggerMap = new ConcurrentHashMap<String, Logger>();
        // force log4j to initialize
        org.apache.log4j.LogManager.getRootLogger();
    }

    @Override
    public Logger getLogger(String name) {
        Logger slf4jLogger = loggerMap.get(name);
        if (slf4jLogger != null) { // 找到直接返回
            return slf4jLogger;
        } else {
            // 先获取log4j的Logger对象
            org.apache.log4j.Logger log4jLogger;
            if (name.equalsIgnoreCase(Logger.ROOT_LOGGER_NAME))
                log4jLogger = LogManager.getRootLogger();
            else
                log4jLogger = LogManager.getLogger(name);

            // 通过 Log4jLoggerAdapter 来将log4j的Logger适配为slf4j的Logger
            Logger newInstance = new Log4jLoggerAdapter(log4jLogger);
            Logger oldInstance = loggerMap.putIfAbsent(name, newInstance);
            return oldInstance == null ? newInstance : oldInstance;
        }
    }
}

逻辑很清楚,接下来的重点就是Log4jLoggerAdapter,这个典型的适配器模式的实现(有删减):

package org.slf4j.impl;

// org.slf4j.spi.LocationAwareLogger 继承了 org.slf4j.Logger 接口
public final class Log4jLoggerAdapter extends MarkerIgnoringBase implements 
    LocationAwareLogger, Serializable {

    final transient org.apache.log4j.Logger logger;

    Log4jLoggerAdapter(org.apache.log4j.Logger logger) {
        this.logger = logger;
    }
    
    // 实现 org.slf4j.Logger 接口中的方法
    @Override
    public void info(String format, Object... argArray) {
        if (logger.isInfoEnabled()) {
            FormattingTuple ft = MessageFormatter.arrayFormat(format, argArray);
            // 实际是通过log4j的API进行打印日志
            logger.log(FQCN, Level.INFO, ft.getMessage(), ft.getThrowable());
        }
    }

    ......
}

通过适配器实现了:当我们编程时面向的是org.slf4j.Logger,而实际执行是通过org.apache.log4j.Logger执行打印日志等操作。

总结

对 slf4j + slf4j-log4j12 + log4j 的运行原理进行一下总结:

  • org.slf4j.LoggerFactory.getLogger(Class)方法的逻辑就是通过ClassLoader查找所有的org.slf4j.impl.StaticLoggerBinder.class,并确定最终实际使用的那一个。

  • StaticLoggerBinder是个单例,并实现了LoggerFactoryBinder接口,用以实现slf4j与日志框架实现之间的绑定。它可以返回一个ILoggerFactory接口的实现类,在 slf4j-log4j12.jar 中是Log4jLoggerFactory

  • Log4jLoggerFactory中必须返回一个org.slf4j.Logger接口的实现类,这个类是Log4jLoggerAdapter

  • Log4jLoggerAdapter是一个典型的适配器模式的实现,它的功能是将log4j的org.apache.log4j.Logger适配成org.slf4j.Logger

  • 当执行org.slf4j.Logger.info()方法时,实际的执行者是Log4jLoggerAdapter.info(),内部是通过log4j的API完成日志的打印。

为什么引入了logback就会破坏之前的日志架构?

通过上面的分析,我们知道StaticLoggerBinder是实现slf4j和日志输出框架之间绑定的桥梁,但如果classpath下有多个StaticLoggerBinder会怎样呢?

实验代码见:https://github.com/wanghui0101/learning-slf4j/tree/master/learning-slf4j-multiple-bindings

pom.xml中添加了logback的jar包。
此时,访问Servlet,控制台会打印2条语句:

Hello Slf4j ! - debug
Hello Slf4j ! - info

并且,在项目启动时,在控制台还会打印出5句错误信息:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/xxx/learning-slf4j-multiple-bindings/WEB-INF/lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/xxx/learning-slf4j-multiple-bindings/WEB-INF/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See 
  for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]

通过之前的源码分析,我们可以得知
第1-4句是org.slf4j.LoggerFactory.reportMultipleBindingAmbiguity(Set<URL>)打印出来的。第5句是org.slf4j.LoggerFactory.reportActualBinding(Set<URL>)打印出来的。
意思就是在classpath下找到了多个StaticLoggerBinder,并自动选择了logback的ContextSelectorStaticBinder。那么,此时slf4j-log4j12.jar就不再起作用,而log4j.xml也不会起作用了。这样,就出现了文章最开始提出的问题中描述的情况那么,为什么会先加载logback的StaticLoggerBinder呢?这是与ClassLoader的类加载机制双亲委派模型有关的。同一个ClassLoader对于同一个类只会加载一次,所以即使classpath下有多个StaticLoggerBinder.class,也只有1个会被加载,而且在我们当前的环境下恰好加载的就是logback的StaticLoggerBinder

因此,对于slf4j来说,查找到多个StaticLoggerBinder.class并不会影响它的执行,只是打印出警告信息而已。

更多关于此问题的解释,见:http://www.slf4j.org/codes.html#multiple_bindings

如何避免类似的冲突?

由于slf4j-log4j12.jar或logback.jar中都包含org/slf4j/impl/StaticLoggerBinder.class,为了不让slf4j加载时产生歧义,需要移除这两者之一,使slf4j只与1个明确的日志实现绑定。记住:始终要保证,在classpath下,只有1个org/slf4j/impl/StaticLoggerBinder.class。

作为服务提供方,我们提供的jar如果依赖了日志相关的jar,应该依赖哪些?

通过上面的分析,如作为服务提供方,依赖的日志jar包,只包括slf4j-api.jar即可。多余的jar包(如slf4j-log4j12.jar或logback.jar),可能会引起服务使用方的日志架构出现问题。

面向slf4j的接口API编程的最佳实践是什么?

尽管可以通过 slf4j-api + slf4j-log4j12 + log4j 或 slf4j-api + logback 实现与底层日志实现框架的绑定,但这样做的前提是项目中所有类,以及依赖的所有jar,都是面向slf4j的API编程。尽管我们可以约束项目组成员,保证所有类都是面向slf4j编程的,但项目所依赖的jar却无法控制。

为此,slf4j还提供了桥接机制,将其它日志实现API,通过slf4j,转换成我们项目中绑定的日志实现。

举例:Spring框架中使用了commons-logging作为了日志输出框架,那么slf4j提供了jcl-over-slf4j.jar将commons-logging的实现先桥接到slf4j,再通过logback输出(如果你选择的日志实现是logback的话)。但是,要注意:如果使用了jcl-over-slf4j.jar,就必须排除commons-logging.jar,因为jcl-over-slf4j.jar中已经包括了commons-logging中的所有类。

另外,一个干净的SpringBoot项目,为我们提供了使用slf4j的最佳实践的范例。根据

https://docs.spring.io/spring-boot/docs/1.5.8.RELEASE/reference/htmlsingle/#getting-started-maven-installation

可以搭建一个干净的SpringBoot项目。它引入的日志相关jar有

  • jcl-over-slf4j.jar // 将commons-logging桥接到slf4j

  • jul-to-slf4j.jar // 将java.util.logging桥接到slf4j

  • log4j-over-slf4j.jar // 将log4j的API桥接到slf4j

  • slf4j-api.jar // slf4j的API

  • logback-classic.jar // logback作为项目的日志实现框架

  • logback-core.jar

这些jar被定义在 spring-boot-starter-logging/pom.xml 中(https://github.com/spring-projects/spring-boot/blob/v1.5.8.RELEASE/spring-boot-starters/spring-boot-starter-logging/pom.xml),我们也可依此,规范项目的日志框架。

更多

  • slf4j关于多次绑定的解释:

http://www.slf4j.org/codes.html#multiple_bindings 

  • slf4j桥接遗留的日志API:

https://www.slf4j.org/legacy.html 

  • slf4j的用户手册:

https://www.slf4j.org/manual.html 


评论
条评论