在看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 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.))
。。。。。
這是因為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 by 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))
這個問題和之前出現的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理解也更加透徹了。