前言
最近做项目,实际上也知道日志冲突的事,不过涉及MDC NDC数据传递,当日志框架冲突后,MDC和NDC就失效了,这里就涉及slf4j-api的MDC的绑定的过程,顺便分析了日志冲突实际生效的原因,理解SLF4J的设计思想。官方网址:SLF4J
Simple Logging Facade for Java(SLF 4J)作为一个简单的facade或抽象,用于各种日志框架(例如logback、log4j2),从而允许最终用户在部署时插入所需的日志记录框架。 简称门面模式,就是接口外加绑定实现。
实际上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.detectLoggerNameMismatch
static 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默认是类全面,也可以自定义字符串,那就是另外的API
if (DETECT_LOGGER_NAME_MISMATCH) {
//通过调用关系取class,securityManager.getClassContext();
//定义slf4j.detectLoggerNameMismatch为true才会生效,默认布尔为false
Class<?> 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; //失败,但有默认factory
case FAILED_INITIALIZATION:
throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG); //失败
case ONGOING_INITIALIZATION:
// support re-entrant behavior.
// See also http://jira.qos.ch/browse/SLF4J-97
return 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-328
if (!isAndroid()) {//判断系统变量java.vendor.url是否包含android字符串
//查找可能的StaticLoggerBinder
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
//如果找到多个就打印在控制台
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
}
// the next line does the binding
// 见上面,StaticLoggerBinder没有实现发现就会报错NoClassDefFound
StaticLoggerBinder.getSingleton();
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION; //状态更新
reportActualBinding(staticLoggerBinderPathSet); //打印实际绑定的binder
} catch (NoClassDefFoundError ncde) { //就是处理刚刚说的异常
String msg = ncde.getMessage();// 下面的信息就是demo在控制台打印的NOP
if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
// no-operation (NOP) logger implementation
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;
}
} 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 {
// 找到SLF4JServiceProvider
List<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 immediately
defaultLoggerContext.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的缘故,门面模式实际上在框架和中间件等开发还是有很关键的作用