在看Java Logging相关的框架、代码、资料的时候，一直有听说Commons Logging存在ClassLoader相关的问题，但是看它的实现代码（1.1.1版本），对ClassLoader做了非常详细的查找：用了Thread Context ClassLoader、System ClassLoader、以及LogFactoryImpl本身的ClassLoader，感觉上已经很全面了。上周末有幸找到一篇Ceki Gülcü写文章，详细介绍了Commons Logging中存在的ClassLoader问题，原文可以参考：http://articles.qos.ch/classloader.html，虽然感觉他对SLF4J解决ClassLoader的问题有点言过其实，但是对问题本身的重现和解释都感觉很详细，也很有参考意义；另外他用的版本是1.0.4 ，而在1.1.1版本中有部分问题已经解决了，但是他所展现的问题对在写一些框架代码以及处理在平时开发中遇到的ClassLoader问题等方面都可以提供比较大的参考价值。因为要在公司讲一个Logging相关的session，所以我需要按自己的理解去解释，顺便把这个过程记录下来，以供以后参考，现在的记性是越来越差了。。。L
我真正开始做Java的时间不长，而且现在在做的项目是一个独立的Application Server，不会用到Web容器相关的服务器，因而没有遇到过Commons Logging存在的ClassLoader的问题，而且在我开始用Tomcat的时候，已经是用Tomcat6了，在Tomcat6中它不再在内部包含commons-logging.jar的引用，因而错过了遇到这个问题的机会，不知道现在在用WebSphere和WebLogic的时候，这个问题是否还会存在。
言归正传，按Ceki Gülcü分类，Commons Logging中的ClassLoader问题可以分成三类：
1. 抛出NoClassDefFoundError，即某个Logger相关的类对child ClassLoader来说是可见的，但是对parent ClassLoader来说则不可见。
2. 非兼容性赋值，即两类虽然相同或存在父子关系，但是由于ClassLoader不一样而导致不可以相互赋值。
3. 用集合对ClassLoader的引用会阻止使用该ClassLoader加载的资源无法被垃圾回收。
对第三个问题，Commons Logging的实现代码在注释中已经有提到，即在LogFactory实现中以ClassLoader作为key缓存了LogFactory的实现实例，虽然Commons Logging中使用了WeakReference技术，ClassLoader在外面被套一层WeakReference以后才存入缓存，但是在比较少见的情况下还是会存在内存泄露的问题：当LogFactory被parent ClassLoader加载（container ClassLoader），而其实现类（LogFactory1）由child ClassLoader加载（component ClassLoader），此时，LogFactory存在对LogFactory1的强引用（通过缓存factories Hashtable），而LogFactory1存在对component ClassLoader的强引用，从而导致component ClassLoader中的资源无法被垃圾回收器正常回收。一般这个问题出现在commons-logging.jar由parent ClassLoader加载，而用户自定义的LogFactory实现由child ClassLoader加载。因而要解决这个问题，则需要确保LogFactory和LogFactory的实现类都由同一个ClassLoader去加载。但是一般情况下，LogFactoryImpl的实现已经足够用了，因而很少会出现用户实现自己的LogFactory，因而这个问题一般很少会出现，而且即使出现了，其表现也不太明显，因而可以基本忽略。
那么接下来主要介绍前面两个问题。要介绍前面两个问题，首先让我们来复习一下Java ClassLoader中的代理机制。在Java中，处于安全的考虑，从1.2开始引入代理机制，即在ClassLoader每次加载一个类时，首先去查找（代理给）parent ClassLoader是否存在该类的定义，如果有，则使用parent ClassLoader加载；否则，使用当前ClassLoader本身去加载该类。这样做可以阻止一些不安全的代码覆盖JDK内部的类，从而实现一些非法操作。Java文档中对该特性的描述如下：
The ClassLoader class uses a delegation model to search for classes and resources. Each instance of ClassLoader has an associated parent class loader. When called upon to find a class or resource, a ClassLoader instance will delegate the search for the class or resource to its parent class loader before attempting to find the class or resource itself. The virtual machine's built-in class loader, called the bootstrap class loader, does not itself have a parent but may serve as the parent of a ClassLoader instance.
因而parent ClassLoader优先是Java中的默认原则。然而在Web Application中却建议使用child ClassLoader优先的机制，从而保证Web Application可以覆盖一些common的配置和JAR包，如Servlet的文档中对Web Application ClassLoader的描述如下：
SRV.9.7.2 Web Application Classloader
The classloader that a container uses to load a servlet in a WAR must allow the developer to load any resources contained in library JARs within the WAR following normal J2SE semantics using getResource. It must not allow the WAR to override J2SE or Java servlet API classes. It is further recommended that the loader not allow servlets in the WAR access to the web container's implementation classes. It is recommended also that the application class loader be implemented so that classes and resources packaged within the WAR are loaded in preference to classes and resources residing in container-wide library JARs.
其实以上这些不管是parent-first代理机制还是child-first代理机制都不是问题，问题出在由于Commons Logging应用太广泛了，导致很多Web服务器在实现时也使用了该包，然而又想保证不同Web Application中的日志配置不相互干扰，这样问题就来了。重现这些问题，我们可以构建一下简单的模型。
1. 准备ClassLoader，因为parent-first ClassLoader是默认的，因而我们可以直接拿JDK内部的ClassLoader：URLClassLoader；而child-first ClassLoader则要自己实现一个（ChildFirstClassLoader），最主要是要覆盖loadClass和getResource两个方法：
protected Class loadClass(String name, boolean resolve) throws ClassNotFoundException {
// First, check if the class has already been loaded
Class c = findLoadedClass(name);
// if not loaded, search the local (child) resources
if (c == null) {
try {
c = findClass(name);
} catch (ClassNotFoundException cnfe) {
// ignore
}
}
// if we could not find it, delegate to parent
// Note that we don't attempt to catch any ClassNotFoundException
if (c == null) {
if (getParent() != null) {
c = getParent().loadClass(name);
} else {
c = getSystemClassLoader().loadClass(name);
}
}
if (resolve) {
resolveClass(c);
}
return c;
}
public URL getResource(String name) {
URL url = findResource(name);
// if local search failed, delegate to parent
if (url == null) {
url = getParent().getResource(name);
}
return url;
}
2. 准备几个实现日志打印的类：
一个LoggerPrinter接口：
public interface LoggerPrinter {
public void printLog();
}
几个不同框架的实现类（JCL、Log4J、SLF4J，他们的实现都是一样）：
public class LoggerPrinterWithJCL implements LoggerPrinter {
@Override
public void printLog() {
Log log = LogFactory.getLog(LoggerPrinterWithJCL.class);
log.info("Print log in class: [" + toString() + "]");
}
public String toString() {
return getClass().getClassLoader().getClass().getName() +
"->" + getClass().getName();
}
}
3. 将LoggerPrinter接口单独打成一个包：loggerprinter.jar，而剩下的实现打成包：loggerprinterimpl.jar。
4. 开始编写测试代码。
首先从Parent-First ClassLoader中存在的问题开始，基本这类问题的测试结构如下：
即在Parent ClassLoader和Child ClassLoader中都引用了commons-logging.jar包，然而只有在Child ClassLoader中存在log4j.jar包，即在使用Child ClassLoader加载的Class运行时希望能用log4j打印日志，而Parent ClassLoader加载的类保持commons-logging的动态查找机制，如果我们使用JDK1.4以上的版本，一般是代理给JDK Logging，那么Commons Logging能满足这样的需求吗？
a. 在没有正确的设置Thread Context ClassLoader的时候。Thread Context ClassLoader的出现是为了解决一个框架在被Parent ClassLoader加载，然而它想加载Child ClassLoader中的类的需求，因而很多框架代码内部会使用Thread Context ClassLoader。比如在LogFactoryImpl的实现中就有很关于使用Thread Context ClassLoader的例子。Thread Context ClassLoader是需要手动设置的，不然默认为Parent Thread中的Thread Context ClassLoader。但是在实际过程中，Thread Context ClassLoader总是不会被正确的设置，比如以下代码注释掉的语句。
public class ParentFirstTestJCL0 {
public static void main(String[] args) throws Exception {
URLClassLoader childClassLoader = new URLClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/commons-logging-1.1.1.jar"),
new URL("file:lib/log4j-1.2.16.jar")
}, ParentFirstTestJCL0.class.getClassLoader());
//Thread.currentThread().setContextClassLoader(childClassLoader);
Log log = LogFactory.getLog(ParentFirstTestJCL0.class);
log.info("message in " + ParentFirstTestJCL0.class.getName());
Class<?> cls = childClassLoader.loadClass("levin.jclproblems.app.LoggerPrinterWithJCL");
LoggerPrinter printer = (LoggerPrinter)cls.newInstance();
printer.printLog();
}
}
使用以下命令运行：
java –cp loggerprinter.jar;tester.jar;lib/commons-logging-1.1.1.jar levin.jclproblems.test.ParentFirstTestJCL0
运行结果是：
2012-11-9 23:20:57 levin.jclproblems.test.ParentFirstTestJCL0 main
信息: message in levin.jclproblems.test.ParentFirstTestJCL0
2012-11-9 23:20:57 levin.jclproblems.app.LoggerPrinterWithJCL printLog
信息: Print log in class: [java.net.URLClassLoader->levin.jclproblems.app.LoggerPrinterWithJCL]
在LoggerPrinterWithJCL类中是能看到log4j包的，但是它依然没有识别，这是因为在没有正确的设置Thread Context ClassLoader时，当前的Thread Context ClassLoader是System ClassLoader。log4j对System ClassLoader是不可见的，而且LogFactory是System ClassLoader加载的，因而LogFactory根本找不到log4j包，从而导致即使在LoggerPrinterWithJCL中的日志打印语句还是使用了JDK Logging。而ParentFirstTestJCL0中使用JDK Logging则比较容易理解了。
b. 那么当我们正确设置Thread Context ClassLoader的时候，会是一个什么结果呢？首先我们使用Commons Logging 1.0.4的版本做测试，并且只运行LoggerPrinter实例中的打印日志功能：
public class ParentFirstTestJCL1 {
public static void main(String[] args) throws Exception {
URLClassLoader childClassLoader = new URLClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/commons-logging-1.0.4.jar"),
new URL("file:lib/log4j-1.2.16.jar")
}, ParentFirstTestJCL1.class.getClassLoader());
Thread.currentThread().setContextClassLoader(childClassLoader);
Class<?> cls = childClassLoader.loadClass("levin.jclproblems.app.LoggerPrinterWithJCL");
LoggerPrinter printer = (LoggerPrinter) cls.newInstance();
printer.printLog();
}
}
Caused by: org.apache.commons.logging.LogConfigurationException: org.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@1f934ad for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category) (Caused by org.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@1f934ad for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category))
at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:543)
.......
它报的是NoClassDefFoundError（Category），也就是说在LoggerPrinterWithJCL类找到了log4j包，但是在初始化Logger实例的时候出错，这是为什么呢？仔细分析我们可以发现，之所以LoggerPrinterWithJCL可以找到log4j包是因为LogFactory在实现时使用了TCCL去查找log4j中的Logger类，然而后来又出现了ClassNotFoundException（Category是Logger父类，要初始化Logger首先需要初始化其父类Catetory）是因为LogFactory这个实例是由System ClassLoader加载的，在Java中，在一个类要加载其他类时，使用加载该类的ClassLoader去加载要加载的类。所以在LogFactory实例去加载log4j中的Logger类时，使用的System ClassLoader，log4j包对System ClassLoader是不可见的，因而出现了ClassNotFoundException。
c. 事实上，Commons Logging 1.1.1版本对这个问题做了优化，虽然不能完全解决，不过至少会做的更加优雅一些。如果我们把版本换成1.1.1的结果如下：
2012-11-9 23:40:34 levin.jclproblems.app.LoggerPrinterWithJCL printLog
信息: Print log in class: [java.net.URLClassLoader->levin.jclproblems.app.LoggerPrinterWithJCL]
也就是当LogFactory发现有ClassNotFoundException时，认为当前的*Log实例不能被初始化，因而它会继续往后面查找，而找到JDK Logging，所以就使用JDK Logging打印日志。
d. 以上是在LoggerPrinterWithJCL中打印日志出现的问题，那么在Tester类中打印日志会出现什么问题呢？让我们看一下接下来的例子（首先使用1.0.4版本）：
public class ParentFirstTestJCL2 {
public static void main(String[] args) throws Exception {
URLClassLoader childClassLoader = new URLClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/commons-logging-1.0.4.jar"),
new URL("file:lib/log4j-1.2.16.jar")
}, ParentFirstTestJCL1.class.getClassLoader());
Thread.currentThread().setContextClassLoader(childClassLoader);
Log log = LogFactory.getLog(ParentFirstTestJCL2.class);
log.info("Message in " + ParentFirstTestJCL2.class.getName());
}
}
这种情况下的结果也是抛异常：
Caused by: org.apache.commons.logging.LogConfigurationException: org.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@913fe2 for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category) (Caused by org.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@913fe2 for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category))
.........
这个时候是NoClassDefFoundError，这个和之前的原因是一样的，因为TCCL的设置，导致在Tester类中的LogFactory也可以通过TCCL看到log4j的包，然而LogFactory在加载Logger类的时候由于LogFactory是由System ClassLoader加载的，而System ClassLoader找不到Logger（Category）类。
e. 同样在1.1.1版本会使用JDK Logging打印日志。
其实除了1.1.1中继续往下查找的机制，Commons Logging还提供了另一种更好的解决方案，即在System ClassLoader只存放commons-logging-api-<version>.jar包，这个包只包含一些基础类，比如LogFactory、LogFactoryImpl、Log类等，而不包含Log的实现类。这样就能保证Log的实现类和log4j的包在ClassLoader层面上是同一层的，因而解决了因为由不同ClassLoader加载而导致对类的可见性不同的问题。
如果在System ClassLoader中只包含commons-logging-api-<version>.jar包，以上的例子都可以很好的跑通（出了第一个没有正确设置TCCL），而且也都使用了log4j来打印日志。
可惜commons-logging-api-<version>.jar在Parent-First ClassLoader模型中是一个非常有效的解决方案，在Child-First ClassLoader中依然会出现问题。
f. 同d中的代码，但是这里使用Child-First ClassLoader模型：
public class ChildFirstTestJCL0 {
public static void main(String[] args) throws Exception {
ChildFirstClassLoader childClassLoader = new ChildFirstClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/commons-logging-1.0.4.jar"),
new URL("file:lib/log4j-1.2.16.jar")
}, ChildFirstTestJCL0.class.getClassLoader());
Thread.currentThread().setContextClassLoader(childClassLoader);
Log log = LogFactory.getLog(ChildFirstTestJCL0.class);
log.info("Message in " + ChildFirstTestJCL0.class.getName());
}
}
这个结果也是抛出异常，不过这个异常的提示是invalid class loader hierarchy：
org.apache.commons.logging.LogConfigurationException: Invalid class loader hierarchy. You have more than one version of 'org.apache.commons.logging.Log' visible, which is not allowed. (Caused by org.apache.commons.logging.LogConfigurationException: Invalid class loader hierarchy. You have more than one version of 'org.apache.commons.logging.Log' visible, which is not allowed.) (Caused by org.apache.commons.logging.LogConfigurationException: org.apache.commons.logging.LogConfigurationException: Invalid class loader hierarchy. You have more than one version of 'org.apache.commons.logging.Log' visible, which is not allowed. (Caused byorg.apache.commons.logging.LogConfigurationException: Invalid class loader hierarchy. You have more than one version of 'org.apache.commons.logging.Log' visible, which is not allowed.))
。。。。。
这是因为Tester中的Log类是由System ClassLoader加载的，而LogFactory使用getLog找到的Log类是由ChildFirstClassLoader加载的，在Java中，两个由不同ClassLoader加载的类，即使加载的是同一个类，他们也是不等价的，对具有父子关系的类，如果ClassLoader不同，子类实例也无法直接赋值给父类，因而产生了这个异常。
g. 同样，在1.1.1版本中对这个问题做了优化，它会使用JDK Logging打印日志，这是因为在1.1.1版本中，当它遇到这种情况时，它会使用Parent ClassLoader继续尝试，这个时候它就能找到兼容的Log实例了。
h. 同b中的代码，如果只使用LoggerPrinterWithJCL打印日志，由于此时所有的包都是全的，因而可以正常的使用log4j打印日志。
i. 那么，如果Child ClassLoader中不包含Commons Logging包呢？
public class ChildFirstTestJCL2 {
public static void main(String[] args) throws Exception {
ChildFirstClassLoader child = new ChildFirstClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/log4j-1.2.16.jar")
}, ChildFirstTestJCL2.class.getClassLoader());
Thread.currentThread().setContextClassLoader(child);
Class<?> cls = child.loadClass("levin.jclproblems.app.LoggerPrinterWithJCL");
LoggerPrinter printer = (LoggerPrinter) cls.newInstance();
printer.printLog();
}
}
此时我们依然会得到异常：
org.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@2f1921 for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category) (Caused byorg.apache.commons.logging.LogConfigurationException: No suitable Log constructor [Ljava.lang.Class;@2f1921 for org.apache.commons.logging.impl.Log4JLogger (Caused by java.lang.NoClassDefFoundError: org/apache/log4j/Category))
这个问题和之前出现的NoClassDefFoundError类似，因而Child-First，所以log4j对ChildClassLoader是可见的，但是LogFactory实例是由System ClassLoader加载的，而log4j对System ClassLoader不可见。同样1.1.1版本做了一些优化，不再详述。
j. 如果在Child ClassLoader中没有包含Commons Logging包时，在Tester类中打印日志会怎么样？结果和i一样，对log4j的可见性是因为设置了TCCL的缘故，其他则一样。
那么在这种情况下有更好的解决方案吗？使用commons-logging-api-<version>.jar的方式是不管用了，其他的我貌似也没有找到比较好的解决方案。道是SLF4J一直声称它解决了ClassLoader的问题，我到感觉在Child-First ClassLoader方式中，即使System ClassLoader的类中使用了SLF4J，它到可以相对来说比较好的解决类似的问题：
public class ChildFirstTestSLF4J0 {
public static void main(String[] args) throws Exception {
ChildFirstClassLoader childClassLoader = new ChildFirstClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/slf4j-api-1.7.2.jar"),
new URL("file:lib/log4j-1.2.16.jar"),
new URL("file:lib/slf4j-log4j12-1.7.2.jar")
}, ChildFirstTestSLF4J0.class.getClassLoader());
Logger log = LoggerFactory.getLogger(ChildFirstTestSLF4J0.class);
log.info("message in {}", ChildFirstTestSLF4J0.class.getName());
Class<?> cls = childClassLoader.loadClass("levin.jclproblems.app.LoggerPrinterWithSLF4J");
LoggerPrinter printer = (LoggerPrinter) cls.newInstance();
printer.printLog();
}
}
使用一下命令运行：
java –cp loggerprinter.jar;tester.jar;/lib/slf4j-api-1.7.2.jar;lib/slf4j-simple-1.7.2.jar levin.jclproblems.test.ChildFirstTestSLF4J0
运行结果：
[main] INFO levin.jclproblems.test.ChildFirstTestSLF4J0 - message in levin.jclproblems.test.ChildFirstTestSLF4J0
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/E:/CodeRepository/Java/log/java_logging_session/lib/slf4j-simple-1.7.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:lib/slf4j-log4j12-1.7.2.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 [org.slf4j.impl.Log4jLoggerFactory]
2012-11-10 00:34:34,274 [main] INFO [LoggerPrinterWithSLF4J.java:10]: Print log in class: [levin.jclproblems.classloader.ChildFirstClassLoader->levin.jclproblems.app.LoggerPrinterWithSLF4J]
除了找到多个绑定包的警告外，它基本保持了Parent ClassLoader和Child ClassLoader的独立性，即在Tester类中使用slf4j-simple-1.7.2.jar包，而在LoggerPrinterWithSLF4J类中使用log4j包。
但是对Parent-First ClassLoader模型来说，SLF4J号称解决，只是因为Parent ClassLoader中的类没有使用SLF4J而已，如果它也使用了SLF4J，它根本没法解决问题：
public class ParentFirstTestSLF4J0 {
public static void main(String[] args) throws Exception {
URLClassLoader childClassLoader = new URLClassLoader(new URL[] {
new URL("file:loggerprinterimpl.jar"),
new URL("file:lib/slf4j-api-1.7.2.jar"),
new URL("file:lib/log4j-1.2.16.jar"),
new URL("file:lib/slf4j-log4j12-1.7.2.jar"),
}, ParentFirstTestJCL0.class.getClassLoader());
Logger log = LoggerFactory.getLogger(ParentFirstTestSLF4J0.class);
log.info("message in {}", ParentFirstTestSLF4J0.class.getName());
Class<?> cls = childClassLoader.loadClass("levin.jclproblems.app.LoggerPrinterWithSLF4J");
LoggerPrinter printer = (LoggerPrinter) cls.newInstance();
printer.printLog();
}
}
使用java命令：
java –cp loggerprinter.jar;tester.jar;lib/slf4j-api-1.7.2.jar;lib/slf4j-simple-1.7.2.jar levin.jclproblems.test.ParentFirstTestSLF4J0
结果是不管Tester类还是LoggerPrinterWithSLF4J中的日志打印都使用了slf4j-simple-1.7.2.jar包，即它的静态绑定机制导致程序在一次绑定后就不能再改变。所以对System ClassLoader中的slf4j-api-1.7.2.jar，它只找到了slf4j-simple-1.7.2.jar的桥接包，这样这种绑定就会一直存在。
其实在这种情况下，slf4j的问题更严重一些，因为如果我们移除System ClassLoader中的slf4j-simple-1.7.2.jar包，那么所有的日志根本不会打印，因为在System ClassLoader中无法找到其他的桥接包，则会导致slf4j绑定失败。
开始看的时候，感觉这个问题比较难，等慢慢熟悉后，才发现其实问题都很相似，也比较简单。因而熟能生巧，真的是很有哲理的一个词。而且感觉这样一个过程下来，对ClassLoader理解也更加透彻了。
