log4j与logback冲突的解决与思考

最新推荐文章于 2024-01-25 20:30:30 发布

Zebul博

最新推荐文章于 2024-01-25 20:30:30 发布

阅读量8k

点赞数 5

转自：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的过程。接下来关注一下具体的过程。

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 http://www.slf4j.org/codes.html#multiple_bindings 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

Zebul博

关注

5
点赞
踩
7

收藏

觉得还不错? 一键收藏
2
评论
log4j与logback冲突的解决与思考

转自：https://www.jianshu.com/p/191a95ad0b89问题在项目启动时，发现打印了大量的debug日志，但是src/main/resources下明明有log4j.xml，而且日志级别还设置的是info，为什么会打印出大量的debug日志呢？分析使用eclipse的Dependency Hierarchy功能可以对pom.xml中定义的jar依赖进行可视...
复制链接

扫一扫