问题
在项目启动时，发现打印了大量的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的最佳实践的范例。根据
可以搭建一个干净的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 中（
），我们也可依此，规范项目的日志框架。
更多
slf4j关于多次绑定的解释：
http://www.slf4j.org/codes.html#multiple_bindings
slf4j桥接遗留的日志API：
https://www.slf4j.org/legacy.html
slf4j的用户手册：
网友评论