Log日志框架启动源码分析

一直以来对于Java中日志类的框架启动流程都一直是黑盒,对于Log4j、commons-logging、Logback以及Slf4j等等这些框架的了解都是停留在基本了解,而不是深入研究。直到碰到了一个大坑,就是项目突然打印了大量的Debug日志,但是又没有方法关闭。以前倒是碰到过相似的问题,找到初步原因是Logback引起的,当时的解决方案就是把Logback移除掉,但是仅仅是简单移除掉并不能回答这个大坑产生的根本原因。因此,本文也是以这个为契机,来看一看到底Log日志在启动的时候做了哪些操作。

项目示例

为了研究这几个框架并存的时候,系统会如何选择日志框架,本文将这几种框架同时引入,并且专门写一个测试类来进行测试,看项目日志是如何初始化的。这里使用的是Apache Commons-Logging门面框架,代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

/**
* @author jiangbo.qjb
* @date 2018/11/4
*/
public class LogTest {

private static final Log log = LogFactory.getLog(LogTest.class);

public static void main(String[] args) {
System.out.println("hello world");
}
}

下面跟着我一起深入到LogFactory.getLog方法里面一探究竟。

源码分析

首先是进入了LogFactory类的getLog方法里面,如下:

1
2
3
public static Log getLog(Class clazz) throws LogConfigurationException {
return (getFactory().getInstance(clazz));
}

org.apache.commons.logging.LogFactory.getLogFactory

这里面比较关键的就是getFactory()方法了,需要拿到一个LogFactory的具体实例,也就是具体实现类,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
public static LogFactory getFactory() throws LogConfigurationException {

// Identify the class loader we will be using
ClassLoader contextClassLoader =
(ClassLoader)AccessController.doPrivileged(
new PrivilegedAction() {
public Object run() {
return getContextClassLoader();
}
});

// Return any previously registered factory for this class loader
LogFactory factory = getCachedFactory(contextClassLoader);
if (factory != null)
return factory;


// Load properties file.
// Will be used one way or another in the end.

Properties props=null;
try {
InputStream stream = getResourceAsStream(contextClassLoader,
FACTORY_PROPERTIES);

if (stream != null) {
props = new Properties();
props.load(stream);
stream.close();
}
} catch (IOException e) {
} catch (SecurityException e) {
}


// First, try the system property
try {
String factoryClass = System.getProperty(FACTORY_PROPERTY);
if (factoryClass != null) {
factory = newFactory(factoryClass, contextClassLoader);
}
} catch (SecurityException e) {
; // ignore
}


// Second, try to find a service by using the JDK1.3 jar
// discovery mechanism. This will allow users to plug a logger
// by just placing it in the lib/ directory of the webapp ( or in
// CLASSPATH or equivalent ). This is similar to the second
// step, except that it uses the (standard?) jdk1.3 location in the jar.

if (factory == null) {
try {
InputStream is = getResourceAsStream(contextClassLoader,
SERVICE_ID);

if( is != null ) {
// This code is needed by EBCDIC and other strange systems.
// It's a fix for bugs reported in xerces
BufferedReader rd;
try {
rd = new BufferedReader(new InputStreamReader(is, "UTF-8"));
} catch (java.io.UnsupportedEncodingException e) {
rd = new BufferedReader(new InputStreamReader(is));
}

String factoryClassName = rd.readLine();
rd.close();

if (factoryClassName != null &&
! "".equals(factoryClassName)) {

factory= newFactory( factoryClassName, contextClassLoader );
}
}
} catch( Exception ex ) {
;
}
}


// Third try a properties file.
// If the properties file exists, it'll be read and the properties
// used. IMHO ( costin ) System property and JDK1.3 jar service
// should be enough for detecting the class name. The properties
// should be used to set the attributes ( which may be specific to
// the webapp, even if a default logger is set at JVM level by a
// system property )

if (factory == null && props != null) {
String factoryClass = props.getProperty(FACTORY_PROPERTY);
if (factoryClass != null) {
factory = newFactory(factoryClass, contextClassLoader);
}
}


// Fourth, try the fallback implementation class

if (factory == null) {
factory = newFactory(FACTORY_DEFAULT, LogFactory.class.getClassLoader());
}

if (factory != null) {
/**
* Always cache using context class loader.
*/
cacheFactory(contextClassLoader, factory);

if( props!=null ) {
Enumeration names = props.propertyNames();
while (names.hasMoreElements()) {
String name = (String) names.nextElement();
String value = props.getProperty(name);
factory.setAttribute(name, value);
}
}
}

return factory;
}

代码有点长,捋一下这段代码的基本逻辑就是要通过下面的一个顺序查找LogFactory的实现类:

  • 查找系统属性(System Property)中是否包含org.apache.commons.logging.LogFactory属性,这个属性会指定它的具体实现类;
  • 基于JDK1.3的服务发现机制,在CLASSPATH中查找包含该服务的Jar包,这个服务的ID就是META-INF/services/org.apache.commons.logging.LogFactory
  • 查找commons-logging.properties文件,对,没错,名称就是这个。找到以后,再到这个文件里面查询上面提到过的org.apache.commons.logging.LogFactory属性;
  • 如果都找不到的话,那就只能指定一个默认的实现类了,org.apache.commons.logging.impl.LogFactoryImpl

补充一下,Factory类有以下几个具体的实现类:

  • org.apache.commons.logging.impl.Log4jFactory
  • org.apache.commons.logging.impl.LogFactoryImpl
  • org.apache.commons.logging.impl.SLF4JLogFactory

这段代码其实有很多种执行的方式,取决于LogFactory这个类具体的实现类是什么,由于本例中存在slf4j的jar包,因此,这段代码由于上述查找机制中的第三条,也就是查找到了META-INF/services/org.apache.commons.logging.LogFactory这个文件,这里可以打开这个文件看一下:

1
2
3
4
5
org.apache.commons.logging.impl.SLF4JLogFactory

# Axis gets at JCL through its own mechanism as defined by Commons Discovery, which
# in turn follows the instructions found at:
# http://java.sun.com/j2se/1.3/docs/guide/jar/jar.html#Service Provider

org.apache.commons.logging.impl.SLF4JLogFactory.getInstance

接着就进入了SLF4JLogFactory.getInstance方法里面了。代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
public Log getInstance(Class clazz) throws LogConfigurationException {
return (getInstance(clazz.getName()));
}

public Log getInstance(String name) throws LogConfigurationException {
Log instance = loggerMap.get(name);
if (instance != null) {
return instance;
} else {
Log newInstance;
Logger slf4jLogger = LoggerFactory.getLogger(name);
if (slf4jLogger instanceof LocationAwareLogger) {
newInstance = new SLF4JLocationAwareLog((LocationAwareLogger) slf4jLogger);
} else {
newInstance = new SLF4JLog(slf4jLogger);
}
Log oldInstance = loggerMap.putIfAbsent(name, newInstance);
return oldInstance == null ? newInstance : oldInstance;
}
}

org.slf4j.LoggerFactory.getLogger

可以看到,这段代码的核心逻辑就是创建一个Logger对象,核心代码是Logger slf4jLogger = LoggerFactory.getLogger(name);,进入这个方法里面去看就能发现Logger被创建的具体细节。

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

这个ILoggerFactory就是一个通过名字(getLogger(name))来查找和管理Logger的类,所以,很显然这里的getILoggerFactory方法就是来根据名称创建LoggerFactory,一般来说,我们的名称是类的全类名,比如com.qinjiangbo.com.log4j.LogTest。这个getILoggerFactory代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
public static ILoggerFactory getILoggerFactory() {
if (INITIALIZATION_STATE == UNINITIALIZED) {
synchronized (LoggerFactory.class) {
if (INITIALIZATION_STATE == UNINITIALIZED) {
INITIALIZATION_STATE = ONGOING_INITIALIZATION;
performInitialization();
}
}
}
switch (INITIALIZATION_STATE) {
case SUCCESSFUL_INITIALIZATION:
return StaticLoggerBinder.getSingleton().getLoggerFactory();
case NOP_FALLBACK_INITIALIZATION:
return NOP_FALLBACK_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;
}
throw new IllegalStateException("Unreachable code");
}

org.slf4j.impl.StaticLoggerBinder.getLoggerFactory

还是要说明一下关键代码,这里的关键代码是StaticLoggerBinder.getSingleton().getLoggerFactory();,可以看到这个StaticLoggerBinder.getSingleton类就是来自于Logback包里面的类,也就是说明Slf4j优先选择的是Logback作为具体实现类。执行这一段的时候,StaticLoggerBinder类里面会默认执行一段init方法,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
static {
SINGLETON.init();
}

void init() {
try {
try {
new ContextInitializer(defaultLoggerContext).autoConfig();
} catch (JoranException je) {
Util.report("Failed to auto configure default logger context", je);
}
// logback-292
if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
}
contextSelectorBinder.init(defaultLoggerContext, KEY);
initialized = true;
} catch (Exception t) { // see LOGBACK-1159
Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
}
}

这里面的这个ContextInitializer类的autoConfig方法非常重要,因为它自动配置了logback的配置信息。具体的逻辑如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
public void autoConfig() throws JoranException {
StatusListenerConfigHelper.installIfAsked(loggerContext);
URL url = findURLOfDefaultConfigurationFile(true);
if (url != null) {
configureByResource(url);
} else {
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 {
BasicConfigurator basicConfigurator = new BasicConfigurator();
basicConfigurator.setContext(loggerContext);
basicConfigurator.configure(loggerContext);
}
}
}

public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
if (url != null) {
return url;
}

url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
if (url != null) {
return url;
}

url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
if (url != null) {
return url;
}

return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
}

上面的这几个常量的名称分别如下:

  • GROOVY_AUTOCONFIG_FILE—>logback.groovy
  • TEST_AUTOCONFIG_FILE—>logback-test.xml
  • AUTOCONFIG_FILE—>logback.xml

这里非常重要的一点:从代码逻辑上可以看出,名称是写死的,并不是什么相似匹配,因此要想让logback配置生效,这里必须写这几个名称。

org.slf4j.LoggerFactory.performInitialization

前面叙述getILoggerFactory方法里面还有一个关键代码就是performInitialization();,这个方法里面包含一个bind方法,具体实现如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
private final static void performInitialization() {
bind();
if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
versionSanityCheck();
}
}

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()) {
staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
}
// the next line does the binding
StaticLoggerBinder.getSingleton();
INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
reportActualBinding(staticLoggerBinderPathSet);
fixSubstituteLoggers();
replayEvents();
// release all resources in SUBST_FACTORY
SUBST_FACTORY.clear();
} catch (NoClassDefFoundError ncde) {
......
} catch (java.lang.NoSuchMethodError nsme) {
......
} catch (Exception e) {
failedBinding(e);
throw new IllegalStateException("Unexpected initialization failure", e);
}
}

初始化成功以后就把状态置为成功了,INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;。其中如果我们导入了多个slf4j的jar包的话,这里会出现绑定冲突,检验冲突的方法就是reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);这个方法的逻辑非常简单,就是看找到的LoggerBinder有多个:

1
2
3
private static boolean isAmbiguousStaticLoggerBinderPathSet(Set<URL> binderPathSet) {
return binderPathSet.size() > 1;
}

ch.qos.logback.classic.LoggerContext.getLogger

然后我们再来看获取Logger的代码iLoggerFactory.getLogger(name);,这里的iLoggerFactory的具体实现类是ch.qos.logback.classic.LoggerContext

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
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;

// check if the desired logger exists, if it does, return it
// without further ado.
Logger childLogger = (Logger) loggerCache.get(name);
// if we have the child, then let us return it without wasting time
if (childLogger != null) {
return childLogger;
}

// if the desired logger does not exist, them create all the loggers
// in between as well (if they don't already exist)
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;
}
}
}

这里我就简单地跟大家说一下他们生成Logger的逻辑好了,如果说你传递过来的名称是Logger.ROOT_LOGGER_NAME也就是字符串ROOT的话,那么直接返回Root Logger。否则就会将我们传递过来的名称,前面说到的比如com.qinjiangbo.com.log4j.LogTest按照分隔符一级一级创建Logger,直到创建完LogTest这一层。

总结

其实顺着这个思路大家把这个启动过程捋一下以后还是会比较清晰的,后面哪一步出现了问题都可以很快地排查到问题所在。下面列举几个常见问题:

项目总是频繁地打印DEBUG级别的日志如何处理

这个首先考虑是否引入了Logback包,因为Logback包会有非常高的优先级,而且它的默认级别就是DEBUG。这里消除它的方法也比较简单,两种方法:

  • 找到logback.xml文件,如果没有就创建一个。在SpringBoot中整合的好像是logback-spring.xml这个文件。大家可以在这个文件里面将日志级别设定为ERROR级别。
  • 排掉Logback包,具体的排包方法大家自行Google。

项目总是报多个SLF4J的实现类冲突

这个是由于在绑定阶段的时候,在类路径上读取到了多个Slf4j的实现类,因此,需要大家花时间排包,排除多余的slf4j的包。

分享到