摘要
本文主要讲解logback日志框架的初始化的全过程,在讲解初始化前先简单介绍了下目前现存的常用日志框架,为后续打下基础,然后进入初始化过程源码解析,大致按如下几块依次分析:
- ILoggerFactory具体实现类LoggerContext的产生
- 通过配置文件或默认配置来配置LoggerContext
- Logger的创建
正文
最近公司好几个同事过来询日志相关的异常,自己对logback也是一知半解,于是便想深入的研究下这个目前比较流行且常用的日志框架。
文中的源码分析主要针对1.2.3版本(不要问我为什么强调版本号,从小写作文凑字数习惯了)。接下来我们直奔主题。
一 常用日志框架简述
在开始今天的主题之前有必要先简单介绍下现存的日志框架,在理清楚各自的关系之后有助于后续的理解。
目前主要存在如下9个日志框架,按具体实现、日志门面和桥接划分如下:
实现类
Log4j
Apache Log4j是一个基于Java的日志记录工具。它是由Ceki Gülcü首创的,现在则是Apache软件基金会的一个项目。 Log4j是几种Java日志框架之一。
Log4j2
Apache Log4j2是apache开发的一款Log4j的升级产品。
Jul (Java Util Logging)
自Java1.4以来的官方日志实现。
Logback
一套日志组件的实现(slf4j阵营), 是目前比较常用的日志框架选择,相比其他日志性能更高,一般与slf4j结合使用。
门面类
Commons Logging
Apache基金会所属的项目,是一套Java日志接口,之前叫Jakarta Commons Logging,后更名为Commons Logging。
Slf4j (Simple Logging Facade for Java)
类似于Commons Logging,是一套简易Java日志门面,本身并无日志的实现。
桥接类
log4j-over-slf4j: 将log4j重定向到slf4j
jcl-over-slf4j: 将commos logging里的Simple Logger重定向到slf4j
jul-to-slf4j: 将Java Util Logging重定向到slf4j
有些人会问为什么要有Slf4j门这些面类,这个问题我也疑惑很久,后来发现在实际环境中我们经常会遇到不同的组件使用的日志框架不同的情况,例如我们常用的Spring Framework使用的是日志组件是Commons logging,分布式一致性解决方案Zookeeper依赖的则是log4j。
这样我在同一项目中就存在不同的组件依赖的多个日志实现框架,但实际只能有一个实现框架存在,所以需要统一日志方案或者统一的日志接口,SLF4J就是这么一个统一的日志接口,通过上面的几个桥接类可以把他们的日志输出重定向到SLF4J,然后 SLF4J 又会根据绑定器把日志交给具体的日志实现工具。
这里特别说名的是logback不需要桥接类去实现logback到SLF4J的重定向,因为logback实现的时候就按照SLF4J的接口去实现的,天然的支持SLF4J,下文也会讲到他们是如何关联的。
二 日志框架初始化全过程
一)获取具体日志实现类LoggerContext
用过logback的小伙伴应该都知道我们在获取Logger的时候不会直接调用logback相关的类(LoggerContext)去getLogger,而是使用org的slf4j-api提供的静态工厂类LoggerFactory的getLogger(Class<?> clazz)方法来获取Logger。而在logback中Logger对象是放在自己的LoggerContext中管理的,所以LoggerFactory.getLogger的过程中必然要先找到实际的日志工厂(ILoggerFactory)实现类LoggerContext(实现了slf4j的ILoggerFactory接口), 具体流程代码如下:
/**
* 类名: org.slf4j.LoggerFactory.class
*/
public static Logger getLogger(String name) {
/**
* 1. 获取logback 的 LoggerContext
* 2. 返回通过LoggerContext(实现了slf4j的ILoggerFactory接口) getLogger的Logger
*/
ILoggerFactory iLoggerFactory = getILoggerFactory();
return iLoggerFactory.getLogger(name);
}
这里的getILoggerFactory是重点,看他如何获取到LoggerContext的
/**
* 类名: org.slf4j.LoggerFactory.class
*
* 返回具体的ILoggerFactory实现实例.
* 这个实例的绑定过程是发生在这个class的编译阶段.
*/
public static ILoggerFactory getILoggerFactory() {
if (INITIALIZATION_STATE == UNINITIALIZED) {
synchronized (LoggerFactory.class) {
if (INITIALIZATION_STATE == UNINITIALIZED) {
INITIALIZATION_STATE = ONGOING_INITIALIZATION;
/**
* 这个初始化方法就是实际绑定LoggerContext的过程,
* 里面有两个方法
* 1. bind() 绑定LoggerContext
* 2. versionSanityCheck()
* 检测当前slf4支持的版本是否满足logback需要的slf4的版本
*/
performInitialization();
}
}
}
switch (INITIALIZATION_STATE) {
case SUCCESSFUL_INITIALIZATION:
return StaticLoggerBinder.getSingleton().getLoggerFactory();
case ...
...
throw new IllegalStateException("Unreachable code");
}
private final static void performInitialization() {
// 绑定LoggerContext
bind();
if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
versionSanityCheck();
}
}
上述代码主要做初始化工作,如果成功了就返回LoggerFactory 实例,即实现了ILoggerFactory的LoggerContext对象。
这段代码的重点是performInitialization()方法里的bind()方法, 她主要获取ILoggerFactory接口具体对象LoggerContext的过程,这里要明白的一点是,实现了ILoggerFactory的接口不一定就是logback的LoggerContext,也有可能是其他日志实现框架里管理Logger的相关对象,如果我们项目里依赖了多个都实现了slf4j的日志框架的话,在这个初始化过程中就会用报冲突,那么我们紧接着看下他是怎么找到,提前透露下,这里实用的是java里的一种spi技术,不明白的可以先自行百度下。
private final static void bind() {
try {
Set<URL> staticLoggerBinderPathSet = null;
if (!isAndroid()) {
/**
* 在ClassLoader里找org.slf4j.impl.StaticLoggerBinder.class
* StaticLoggerBinder是实现slf4j里的LoggerFactoryBinder接口的类,
* 由具体的日志实现框架去实现的。
* 找到后返回这些StaticLoggerBinder的URI列表,为什么会是列表,是因为
* 我们项目中可能不止依赖一直日志实现框架,
* 但是这些日志框架又不能并存,所有需要做个判断,
* 紧接的reportMultipleBindingAmbiguity()方法就是这个作用
* 她主要是判断返回的列表中是否有多个StaticLoggerBinder,并打出相应提示日志。
*/
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
}
/**
* 正常的绑定动作
* 上面的findPossibleStaticLoggerBinderPathSet()方法已经在ClassLoader里找过了
* StaticLoggerBinder类,假设我们找到了,那么通过他的静态方法getSingleton()获取
* 自己的实例。
*/
StaticLoggerBinder.getSingleton();
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
reportActualBinding(staticLoggerBinderPathSet);
fixSubstituteLoggers();
replayEvents();
// release all resources in SUBST_FACTORY
SUBST_FACTORY.clear();
/**
* 一大串异常处理,便于我们使用的排查问题,打出的一些日志我们经常会看到,所以这里没有省略掉,
* 可以留意下,有助于以后排查问题。
*/
} 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;
}
} 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);
}
}
上面代码注释里已经说了bind() 方法先是在ClassLoader里找org.slf4j.impl.StaticLoggerBinder.class,可能会有多个,一并返回给staticLoggerBinderPathSet,紧接着检查是否有多个StaticLoggerBinder,如果有多个则打出日志,便于我们排查,然后做实际的绑定动作。即StaticLoggerBinder.getSingleton(),因为我们研究的是logback,所有我们假设StaticLoggerBinder就是logback实现的,看下这个类以及里面重要的init()方法:
public class StaticLoggerBinder implements LoggerFactoryBinder {
/**
* 需求的slf4j的版本号,上面代码中有个versionSanityCheck()方法就是用到这个成员变量去检测的
*/
public static String REQUESTED_API_VERSION = "1.7.16"; // !final
final static String NULL_CS_URL = CoreConstants.CODES_URL + "#null_CS";
/**
* The unique instance of this class.
*/
private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();
private static Object KEY = new Object();
static {
SINGLETON.init();
}
private boolean initialized = false;
/**
* Logger管理类,
* 就是具体实现slf4j的ILoggerFactory接口的实例对象.
*/
private LoggerContext defaultLoggerContext = new LoggerContext();
private final ContextSelectorStaticBinder contextSelectorBinder = ContextSelectorStaticBinder.getSingleton();
private StaticLoggerBinder() {
defaultLoggerContext.setName(CoreConstants.DEFAULT_CONTEXT_NAME);
}
public static StaticLoggerBinder getSingleton() {
return SINGLETON;
}
...
/**
* 初始化loggerContext的方法.
* 重点是new ContextInitializer(defaultLoggerContext).autoConfig()
*/
void init() {
try {
try {
/**
* 重点
* ContextInitializer类主要是用来作具体具体程度loggerContext初始化工作
* 她会更好logback.xml或者默认的配置来定义loggerContext
*/
new ContextInitializer(defaultLoggerContext).autoConfig();
} catch (JoranException je) {
Util.report("Failed to auto configure default logger context", je);
}
...
initialized = true;
} catch (Exception t) { // see LOGBACK-1159
Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
}
}
public ILoggerFactory getLoggerFactory() {
...
}
...
}
上面这段代码中,StaticLoggerBinder类主要维护这一个LoggerContext成员变量,
她通过new ContextInitializer(defaultLoggerContext).autoConfig()对这LoggerContext进行初始化,
最后可通过getLoggerFactory()获取LoggerContext,至此整个LoggerContext获取过程结束。
二)加载配置过程
public class ContextInitializer {
final public static String GROOVY_AUTOCONFIG_FILE = "logback.groovy";
final public static String AUTOCONFIG_FILE = "logback.xml";
final public static String TEST_AUTOCONFIG_FILE = "logback-test.xml";
final public static String CONFIG_FILE_PROPERTY = "logback.configurationFile";
final LoggerContext loggerContext;
public ContextInitializer(LoggerContext loggerContext) {
this.loggerContext = loggerContext;
}
/**
* 配置LoggerContext
*/
public void autoConfig() throws JoranException {
StatusListenerConfigHelper.installIfAsked(loggerContext);
/**
* logback 配置文件有两种格式 .xml 和 .groovy
* .xml类型又有2个名称logback-test.xml和logback.xml
* 所以供有 logback-test.xml、logback.grovy和logback.xml
* logback提供内置配置和外置配置2种配置方式,
* 优先找外置配置,通过启动参数-Dlogback.configurationFile= 具体配置文件Path,来配置
* 内置配置找classpath路径底下,依次按照logback-test.xml、logback.grovy和logback.xml
* 顺序来查找,直到找到为止。
* 以后就是findURLOfDefaultConfigurationFile()方法的逻辑
*
*/
URL url = findURLOfDefaultConfigurationFile(true);
if (url != null) {
/* 通过找到的配置文件来进行配置 */
configureByResource(url);
} else {
/**
* 如果无配置文件,这里通过spi找到实现了Configurator接口的配置服务类来用于配置
*/
Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
if (c != null) {
try {
c.setContext(loggerContext);
c.configure(loggerContext);
} catch (Exception e) {
throw new LogbackException(String.format("Failed to initialize Configurator: %s using ServiceLoader", c != null ? c.getClass()
.getCanonicalName() : "null"), e);
}
} else {
/**
* 如果连Configurator服务类都没有的话,logback还提供一个BasicConfigurator,
* 她只会对Console打日志。
*/
BasicConfigurator basicConfigurator = new BasicConfigurator();
basicConfigurator.setContext(loggerContext);
basicConfigurator.configure(loggerContext);
}
}
}
...
/**
* 配置文件数量的管理,并作相应提示
*/
private void multiplicityWarning(String resourceName, ClassLoader classLoader) {
Set<URL> urlSet = null;
StatusManager sm = loggerContext.getStatusManager();
try {
urlSet = Loader.getResources(resourceName, classLoader);
} catch (IOException e) {
sm.add(new ErrorStatus("Failed to get url list for resource [" + resourceName + "]", loggerContext, e));
}
if (urlSet != null && urlSet.size() > 1) {
sm.add(new WarnStatus("Resource [" + resourceName + "] occurs multiple times on the classpath.", loggerContext));
for (URL url : urlSet) {
sm.add(new WarnStatus("Resource [" + resourceName + "] occurs at [" + url.toString() + "]", loggerContext));
}
}
}
}
至此整个加载配置过程完成,这里没有详细分析logback如何去解析.xml配置文件,以及如何做配置的,后续有想法再做分析。
三)LoggerContext getLogger 过程
上面分析了整个分析了LoggerContext的生成及配置过程,回头我们再看下这个类主要是干嘛的,
首先这个类中有个成员变量private Map<String, Logger> loggerCache用来缓存所有的Logger,key 就是对应的Logger 名称。
另外,上面一直说LoggerContext实现了ILoggerFactory接口,这个接口很简单,简单到只有一个方法,就是获取Logger对象
public interface ILoggerFactory {
public Logger getLogger(String name);
}
我们联想一下,getLogger()方法中会不会将新创建Logger 放入loggerCache ?那又是如何创建的?
带着这些疑问我们我们来就重点分析下这个getLogger(String name)方法。
public final Logger getLogger(final String name) {
if (name == null) {
throw new IllegalArgumentException("name argument cannot be null");
}
// if we are asking for the root logger, then let us return it without
// wasting time
if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
return root;
}
int i = 0;
Logger logger = root;
/**
* 这里先从缓存从找,找到了直接返回
* 这里变量取名为childLogger 会有些迷惑,我们可能把她理解为根日志root的child
* 这样更好理解点,我们要知道logback总是存在一个根Logger,
* 在LoggerContext默认构造函数中会new一个名称为ROOT的Logger作为根日志.
*/
Logger childLogger = (Logger) loggerCache.get(name);
// if we have the child, then let us return it without wasting time
if (childLogger != null) {
return childLogger;
}
/**
* 程序执行到这里那么肯定是当前需求的日志还没有被创建,
* 举个栗子:
* 假如我们有个com.cw.logback.Demo.class 类,
* 这个类中我们通过 LoggerFactory.getLogger(Demo.class)
* 来生成个Logger, 那么我们最终一定会获取一个名称为 ”com.cw.logback.Demo“的Logger
* 那么在这个Logger的创建过程中是不是就只产生这一个对象能?
* 显然不是,下面整个while循环内会根据com.cw.logback.Demo.class 类名
* 以DOT(.)号从左到右依次创建名称分别为
* com|com.cw|com.cw.logback|com.cw.logback.Demo
* 这4个Logger类,且左Logger为右的父级,当然他们有个共同的父级ROOT Logger。
* 为什么logback要维护这种父子关系?
* 这涉及到Logger绑定的Appender, 关系到具体打印日志时的一个传递特性,具体下一篇文章再详细说明.
*/
String childName;
while (true) {
int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
if (h == -1) {
childName = name;
} else {
childName = name.substring(0, h);
}
// move i left of the last point
i = h + 1;
synchronized (logger) {
childLogger = logger.getChildByName(childName);
if (childLogger == null) {
childLogger = logger.createChildByName(childName);
loggerCache.put(childName, childLogger);
incSize();
}
}
logger = childLogger;
if (h == -1) {
return childLogger;
}
}
}
至此整个LoggerFactory.getLogger() 的过程结束。
三 总结
回顾整个logback日志框架结合slf4j的初始化过程,先时运用spi技术查找到实际实现slf4j的ILoggerFactory接口的LoggerContext类进行实例化,然后加载配置文件或默认配置类对LoggerContext实例进行相关配置,最后根据所有需要使用日志的类的类名来创建对应的父子Logger对象并存入缓存。
通过对这段初始化源码的分析,更深入的了解了logback的初始化机制,对后续项目启动出现的日志相关异常的排查有很大帮助,例如基本的日志jar包冲突以及配置文件加载可能存在的异常排查等。
因个人水平有限,文中可能出现这样那样的错误,欢迎大家指正、共勉。