SLF4J日志绑定原理分析

前言

最近做项目，实际上也知道日志冲突的事，不过涉及MDC NDC数据传递，当日志框架冲突后，MDC和NDC就失效了，这里就涉及slf4j-api的MDC的绑定的过程，顺便分析了日志冲突实际生效的原因，理解SLF4J的设计思想。官方网址：SLF4J

Simple Logging Facade for Java（SLF 4J）作为一个简单的facade或抽象，用于各种日志框架（例如logback、log4j2），从而允许最终用户在部署时插入所需的日志记录框架。简称门面模式，就是接口外加绑定实现。

click to enlarge

实际上slf4j-api原生支持的日志框架主要有2种logback和log4j2，其他JDK日志log4j1、commons-logging等都是桥接到slf4j-api的。

桥接都是slf4j自己实现的，对应上面的架构图，MIT协议，所以商业用途可以修改源代码。

slf4j-api 1.x

直接code吧，源码说明问题，先使用slf4j-api 1.7.36版本为例

public class Main {private static final Logger LOGGER = LoggerFactory.getLogger(Main.class);public static void main(String[] args) {System.out.println("hello log");LOGGER.info("first slf4j-api logger!");}
}

很简单的代码，执行后

出现红字，那么就来分析红字的来源，从getLogger开始，因为info这些方法，实际上是接口方法，关键还是创建的slf4j-api的Logger的实现

  // Support for detecting mismatched logger names.static final String DETECT_LOGGER_NAME_MISMATCH_PROPERTY = "slf4j.detectLoggerNameMismatch";static final String JAVA_VENDOR_PROPERTY = "java.vendor.url";//通过系统变量读取slf4j.detectLoggerNameMismatchstatic boolean DETECT_LOGGER_NAME_MISMATCH = Util.safeGetBooleanSystemProperty(DETECT_LOGGER_NAME_MISMATCH_PROPERTY);static final String CODES_PREFIX = "http://www.slf4j.org/codes.html";static final String LOGGER_NAME_MISMATCH_URL = CODES_PREFIX + "#loggerNameMismatch";public static Logger getLogger(Class<?> clazz) {Logger logger = getLogger(clazz.getName()); //关键代码，获取Logger对象，class默认是类全面，也可以自定义字符串，那就是另外的APIif (DETECT_LOGGER_NAME_MISMATCH) {//通过调用关系取class，securityManager.getClassContext();//定义slf4j.detectLoggerNameMismatch为true才会生效，默认布尔为falseClass<?> autoComputedCallingClass = Util.getCallingClass();if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {//这里report就是system.err就是控制台红字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;}

然后继续看getLogger

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

没什么讲的，过度代码，获取factory接口实现，然后获取logger实现，ILoggerFactory实际上也是需要logback或者log4j2自己需要实现的，实现的来源于StaticLoggerBinder

    public static ILoggerFactory getILoggerFactory() {//状态机制if (INITIALIZATION_STATE == UNINITIALIZED) {//未初始化，同步初始化synchronized (LoggerFactory.class) {if (INITIALIZATION_STATE == UNINITIALIZED) {INITIALIZATION_STATE = ONGOING_INITIALIZATION; //更新状态performInitialization(); //关键逻辑，初始化factory实现}}}switch (INITIALIZATION_STATE) {case SUCCESSFUL_INITIALIZATION: //成功//注意这个StaticLoggerBinder在slf4j-api是没有定义的，绑定器单例获取factory，这里很可能NoClassDefFound抛异常return StaticLoggerBinder.getSingleton().getLoggerFactory(); case NOP_FALLBACK_INITIALIZATION:return NOP_FALLBACK_FACTORY; //失败，但有默认factorycase FAILED_INITIALIZATION:throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG); //失败case ONGOING_INITIALIZATION:// support re-entrant behavior.// See also http://jira.qos.ch/browse/SLF4J-97return SUBST_FACTORY; //重入行为，再次创建factory}throw new IllegalStateException("Unreachable code");}

源码可以看到这个类飘红了，jar包里面是没有这个类的，但是类不存在编译不过，猜测是slf4j-api有依赖类，打包剔除的，等源码分析后看github看看

关键还是performInitialization

    private final static void performInitialization() {bind();if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {versionSanityCheck();//成功初始化检查版本号}}

看看检查版本号，推测slf4j-api的1.6和1.7是兼容的，但是不兼容slf4j-api 2.x

关键还是bind方法

    private final static void bind() {try {Set<URL> staticLoggerBinderPathSet = null;// skip check under android, see also// http://jira.qos.ch/browse/SLF4J-328if (!isAndroid()) {//判断系统变量java.vendor.url是否包含android字符串//查找可能的StaticLoggerBinderstaticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet(); //如果找到多个就打印在控制台reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);}// the next line does the binding// 见上面，StaticLoggerBinder没有实现发现就会报错NoClassDefFoundStaticLoggerBinder.getSingleton();INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION; //状态更新reportActualBinding(staticLoggerBinderPathSet); //打印实际绑定的binder} catch (NoClassDefFoundError ncde) { //就是处理刚刚说的异常String msg = ncde.getMessage();// 下面的信息就是demo在控制台打印的NOPif (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {// no-operation (NOP) logger implementationINITIALIZATION_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;}} catch (java.lang.NoSuchMethodError nsme) {String msg = nsme.getMessage(); //很明显就是1.6和1.7不兼容1.5的情况，方法变了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);} finally {postBindCleanUp();//替代日志factory，报告事件，实际上就是控制台打印}}

查找逻辑也很简单，关键在于类定义和查找，实际上Spring也经常有这种逻辑处理，类只有类名，只定义标准

如果有多个就打印出来

    private static boolean isAmbiguousStaticLoggerBinderPathSet(Set<URL> binderPathSet) {return binderPathSet.size() > 1;}/*** Prints a warning message on the console if multiple bindings were found* on the class path. No reporting is done otherwise.* */private static void reportMultipleBindingAmbiguity(Set<URL> binderPathSet) {if (isAmbiguousStaticLoggerBinderPathSet(binderPathSet)) {Util.report("Class path contains multiple SLF4J bindings.");for (URL path : binderPathSet) {Util.report("Found binding in [" + path + "]");}Util.report("See " + MULTIPLE_BINDINGS_URL + " for an explanation.");}}

实际使用那个Binder

MDC同理

同时石锤slf4j-api开发过程中有实现Binder

打包去掉类，或许我们也可以这样，在特定时刻，方便框架开发，业务实现一般不会这样用。

slf4j-api 2.x

为什么会单独介绍2.x版本，架构变了，笔者在查看github，发现slf4j-api的master即2.x的最新代码，真的使用SPI了，同时意味着刚刚的Binder实现类在源码移除了

截止现在slf4j-api最新版是2.0.7，查看源码

   public static ILoggerFactory getILoggerFactory() {return getProvider().getLoggerFactory();}static SLF4JServiceProvider getProvider() {if (INITIALIZATION_STATE == 0) {Class var0 = LoggerFactory.class;synchronized(LoggerFactory.class) {if (INITIALIZATION_STATE == 0) {INITIALIZATION_STATE = 1;performInitialization();}}}switch (INITIALIZATION_STATE) {case 1:return SUBST_PROVIDER;case 2:throw new IllegalStateException("org.slf4j.LoggerFactory in failed state. Original exception was thrown EARLIER. See also https://www.slf4j.org/codes.html#unsuccessfulInit");case 3:return PROVIDER;case 4:return NOP_FALLBACK_SERVICE_PROVIDER;default:throw new IllegalStateException("Unreachable code");}}

实际上根1.x是一样的，方法名称变了，具体是否使用SPI，还要看performInitialization

    private final static void bind() {try {// 找到SLF4JServiceProviderList<SLF4JServiceProvider> providersList = findServiceProviders();reportMultipleBindingAmbiguity(providersList); // 多个打印if (providersList != null && !providersList.isEmpty()) { // 多个实现，使用SPI的第一个PROVIDER = providersList.get(0);// SLF4JServiceProvider.initialize() is intended to be called here and nowhere else.PROVIDER.initialize(); //初始化，因为判空的缘故，所以正常情况不会出现类未定义的异常INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;reportActualBinding(providersList); //实际绑定} else {// 没有的时候，就是1.x控制台不引入任何日志jar的内容，提示有变化INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;Util.report("No SLF4J providers were found.");Util.report("Defaulting to no-operation (NOP) logger implementation");Util.report("See " + NO_PROVIDERS_URL + " for further details.");//老式查找，因为SPI了，所以忽略加载了Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();reportIgnoredStaticLoggerBinders(staticLoggerBinderPathSet);}postBindCleanUp();//替代factory，reportEvent} catch (Exception e) {failedBinding(e);throw new IllegalStateException("Unexpected initialization failure", e);}}

Java SPI加载逻辑，加载后取第一个生效

MDC同理，实际上看1.x的源码，还有一个Marker的接口也是同样的道理

没有任何日志jar的打印

NOP模式

logback实现

因为logback和log4j2实现都差不多，所以以logback为例，因为Springboot内置

以slf4j-api 2.0.7和logback 1.4.8为例

先看logback classic的SPI配置

文件内容就是实现类

ch.qos.logback.classic.spi.LogbackServiceProvider

先看initialize方法，在slf4j-api的bind方法中会被调用

    public void initialize() {defaultLoggerContext = new LoggerContext();defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);initializeLoggerContext();defaultLoggerContext.start();markerFactory = new BasicMarkerFactory();mdcAdapter = new LogbackMDCAdapter();// set the MDCAdapter for the defaultLoggerContext immediatelydefaultLoggerContext.setMDCAdapter(mdcAdapter);}

初始化日志套件，关键是LoggerContext，有Marker和MDC的工厂或者适配器的创建，这2个也是日志的SPI机制附加的

public static ILoggerFactory getILoggerFactory() {return getProvider().getLoggerFactory();
}

logback的工厂就是initialize的defaultLoggerContext

然后创建logger，这个实际上就是层级创建，因为这个设计，所以logger天然适合MDC传输数据，比如线程id

log4j2实际上也差不多，据测试log4j2的性能比logback强一些，笔者没测试过，实际应用也不会特别考虑这个原因，因为Boot集成了，而且logback性能也不差。另外logback和log4j2实际上不同配置也会造成性能差异，比如是否阻塞和是否丢日志的抉择等，可以查询官方，适配详细参数。

日志冲突分析

日志冲突跟slf4j-api加载多个实现或者桥接器有关，表现为加载多个Binder或者SPI实现，但是实际加载的不是我们想要的，如果加载log4j1这样的，很可能slf4j-api的System.err都不会打印，只能删掉除了slf4j-api的其他所有日志jar，一个一个排查，如果fatjar压入了日志jar的源码，那么只能class扫描才行。

日志冲突跟slf4j-api加载的过程有关：

1.6、1.7的版本是类实际加载的时间有关，那么这个就跟Maven依赖顺序，打Spring Boot包是否排序有关
2.x的版本跟Java SPI的配置文件加载时间有关，也是跟jar的加载顺序有关

最长见的是外置Tomcat，非embed tomcat，tomcat7会对lib目录排序，tomcat8的lib目录就是解压后的操作系统决定顺序，导致不同机器运行后日志冲突不一致，解决办法也简单，外置tomcat也支持不解压运行，可以看tomcat源码，或者使用Spring boot这样内嵌tomcat，打包就把顺序固定。

笔者故意冲突

实际就会打印

如果我调换依赖顺序

因为我没有log4j的实现，所以日志是打印不出来的。

总结

实际上这些原理一般不需要了解也可以正常打印日志，现在开发都考虑到各种问题了，所以有了Spring Boot这种一体jar，包打好了就固定了，不过出问题需要会查问题即可。另外吐槽golang的日志框架，真的五花八门，一般用的Uber-go的zap包，但是K8S docker又是另外的，实际上有接口注入还好，可以自定义，如果没提供接口注入就彻底不能动了，只能在框架重新实现，就是没有slf4j-api的缘故，门面模式实际上在框架和中间件等开发还是有很关键的作用