Tomcat原始碼研究之Logger
阿新 • • 發佈：2019-01-10
嗯，終於到主角了
1. 概述
上一篇文章JDK研究之Logger中，我們初略瞭解了JDK中提供的Log實現。而Tomcat是在此基礎之上做的改動。
Tomcat內部的日誌實現，是使用JULI——這是apache commons logging改名後的一個專案。
2. 配置檔案logging.properties
Tomcat中為了增加自定義的Log配置，同時不影響其它使用JDK中的Log的應用，所以指定了自定義的logger配置檔案logging.properties。
2.1 配置檔案的配置
Tomcat是通過在啟動指令碼catalina.bat中增加引數來自定義配置的載入的。
即啟動引數中包含兩個-D引數
1. java.util.logging.config.file
2. java.util.logging.manager
這一點可以從下面的《Tomcat啟動後的JVM引數圖》中得到驗證。
2.2 讀取位置
logging.properties配置檔案有兩個讀取位置：
1. 專案的classpath之下（即webapps/{project}/WEB-INF/classes下）的，注意這裡有著相比較於第二個的高優先順序。
2. 然後才是Tomcat的預設位置${CATALINA_HOME}/conf目錄下。
2.1.1 衍生技巧
這裡就衍生出了一個技巧。如果你的Tomcat在啟動時出錯，但錯誤原因又非常晦澀時，往往是因為錯誤日誌太簡單。這時候的你就需要降低Tomcat日誌的級別，此時 你可以進行如下操作：
- 在專案的
WEB-INF/classes下新增一個logging.properties檔案。 向第一步新增的
logging.properties檔案中加入如下內容：handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler org.apache.juli.FileHandler.level = FINE org.apache.juli.FileHandler.directory = ${catalina.base}/logs org.apache.juli.FileHandler.prefix = error-debug. java.util.logging.ConsoleHandler.level = FINE java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter至此，我們再啟動tomcat時，就會在logs目錄下生成一個更詳細的日誌error-debug.YYYY-MM-dd.log。
- 排錯結束後，我們就只需要刪除掉該配置檔案，就可以將Tomcat恢復到預設狀態。
2.2 配置檔案解析
然後我們來看看這個配置檔案，看看裡面的內容都是怎麼解析的，我們將預設的配置內容分為三部分。
2.2.1 第一段配置的解析
我們先來看看第一段配置
handlers = 1catalina.org.apache.juli.FileHandler, 2localhost.org.apache.juli.FileHandler, 3manager.org.apache.juli.FileHandler, 4host-manager.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler以上這一段是在 ClassLoaderLogManager.readConfiguration 中完成的
protected synchronized void readConfiguration(InputStream is, ClassLoader classLoader)
throws IOException {
ClassLoaderLogInfo info = classLoaderLoggers.get(classLoader);
// 以下為了節省篇幅，省略了異常處理的程式碼
// 載入logging.properties 檔案
info.props.load(is);
// Create handlers for the root logger of this classloader
// 就是在這裡讀取上面的兩個配置檔案節點
String rootHandlers = info.props.getProperty(".handlers");
String handlers = info.props.getProperty("handlers");
Logger localRootLogger = info.rootNode.logger;
if (handlers != null) {
// 按 , 分割
StringTokenizer tok = new StringTokenizer(handlers, ",");
while (tok.hasMoreTokens()) {
String handlerName = (tok.nextToken().trim());
String handlerClassName = handlerName;
String prefix = "";
if (handlerClassName.length() <= 0) {
continue;
}
// Parse and remove a prefix (prefix start with a digit, such as "10WebappFooHanlder.")
// 注意上面的配置資訊裡, 首字母就是數字的
if (Character.isDigit(handlerClassName.charAt(0))) {
int pos = handlerClassName.indexOf('.');
if (pos >= 0) {
// 這裡的prefix形如 1catalina , 2localhost, 3manager, 4host-manager.
prefix = handlerClassName.substring(0, pos + 1);
// 這裡的handlerClassName形如 org.apache.juli.FileHandler
handlerClassName = handlerClassName.substring(pos + 1);
}
}
try {
// this.prefix型別為 ThreadLocal<String>
// 使用該prefix的位置位於 ClassLoaderLogManager 覆寫的getProperty方法中
this.prefix.set(prefix);
Handler handler =
(Handler) classLoader.loadClass(handlerClassName).newInstance();
// The specification strongly implies all configuration should be done
// during the creation of the handler object.
// This includes setting level, filter, formatter and encoding.
this.prefix.set(null);
// 鍵值對的形式存入, 這裡也體現出了數字字首的用處
info.handlers.put(handlerName, handler);
if (rootHandlers == null) {
localRootLogger.addHandler(handler);
}
} catch (Exception e) {
// Report error
System.err.println("Handler error");
e.printStackTrace();
}
}
}
}2.2.2 第二段配置的解析
然後是配置檔案中的第二段配置
############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################
1catalina.org.apache.juli.FileHandler.level = FINE
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.
2localhost.org.apache.juli.FileHandler.level = FINE
2localhost.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.FileHandler.prefix = localhost.
3manager.org.apache.juli.FileHandler.level = FINE
3manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
3manager.org.apache.juli.FileHandler.prefix = manager.
4host-manager.org.apache.juli.FileHandler.level = FINE
4host-manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
4host-manager.org.apache.juli.FileHandler.prefix = host-manager.
java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter以上這段配置檔案可以參見 org.apache.juli.FileHandler.configure方法，以及org.apache.juli.FileHandler.getProperty方法【其在內部呼叫了LogManager.getProperty(name)，而我們的ClassLoaderLogManager正好是覆寫了這個方法的】
// org.apache.juli.FileHandler.configure
/**
* Configure from <code>LogManager</code> properties.
*/
private void configure() {
// 截取出形如 2018-07-01 的日期; 用於組裝日誌檔名
Timestamp ts = new Timestamp(System.currentTimeMillis());
String tsString = ts.toString().substring(0, 19);
date = tsString.substring(0, 10);
String className = this.getClass().getName(); //allow classes to override
ClassLoader cl = Thread.currentThread().getContextClassLoader();
// Retrieve configuration of logging file name
// 注意這裡的getProperty方法有自定義邏輯, 下方貼出具體實現
// rotatable ： 日誌檔案是否自動輪轉
rotatable = Boolean.parseBoolean(getProperty(className + ".rotatable", "true"));
// 日誌檔案所在的目錄
if (directory == null)
directory = getProperty(className + ".directory", "logs");
// 日誌檔名的字首
if (prefix == null)
prefix = getProperty(className + ".prefix", "juli.");
// 日誌檔名的字尾
if (suffix == null)
suffix = getProperty(className + ".suffix", ".log");
String sBufferSize = getProperty(className + ".bufferSize", String.valueOf(bufferSize));
try {
bufferSize = Integer.parseInt(sBufferSize);
} catch (NumberFormatException ignore) {
//no op
}
// Get encoding for the logging file
String encoding = getProperty(className + ".encoding", null);
if (encoding != null && encoding.length() > 0) {
try {
setEncoding(encoding);
} catch (UnsupportedEncodingException ex) {
// Ignore
}
}
// Get logging level for the handler
setLevel(Level.parse(getProperty(className + ".level", "" + Level.ALL)));
// Get filter configuration
String filterName = getProperty(className + ".filter", null);
if (filterName != null) {
try {
setFilter((Filter) cl.loadClass(filterName).newInstance());
} catch (Exception e) {
// Ignore
}
}
// Set formatter
String formatterName = getProperty(className + ".formatter", null);
if (formatterName != null) {
try {
setFormatter((Formatter) cl.loadClass(formatterName).newInstance());
} catch (Exception e) {
// Ignore and fallback to defaults
setFormatter(new SimpleFormatter());
}
} else {
setFormatter(new SimpleFormatter());
}
// Set error manager
setErrorManager(new ErrorManager());
}
private String getProperty(String name, String defaultValue) {
// 直接回調LogManager的getProperty方法
// 而Tomcat中使用的自定義LogManager【ClassLoaderLogManager】是覆寫了這個方法的.
String value = LogManager.getLogManager().getProperty(name);
if (value == null) {
value = defaultValue;
} else {
value = value.trim();
}
return value;
}我們擷取上面配置檔案中的一行配置，來進行一番分析，以便於理解。
1catalina.org.apache.juli.FileHandler.level = FINE
// 其中
// 1. 1catalina由 ClassLoaderLogManager.getProperty中的 this.prefix.get() 提供
// 2. org.apache.juli.FileHandler 由 FileHandler.configure中的classname提供
// 3. levle才是真正需要取的屬性值對應的屬性名2.2.3 第三段配置的解析
然後是第三段配置
############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = 3manager.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].handlers = 4host-manager.org.apache.juli.FileHandler這一段解析邏輯就需要去容器基類ContainerBase類中
/**
* Return the abbreviated name of this container for logging messages
*/
protected String logName() {
// 返回快取的 log name
if (logName != null) {
return logName;
}
// 就是這裡生成org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager]這樣格式的名稱，
// 其中被 [ ] 包裹的名字 是在 server.xml中定義的 ; 形如 <Engine defaultHost="localhost" name="Catalina"> ;
String loggerName = null;
Container current = this;
while (current != null) {
String name = current.getName();
if ((name == null) || (name.equals(""))) {
name = "/";
} else if (name.startsWith("##")) {
name = "/" + name;
}
loggerName = "[" + name + "]"
+ ((loggerName != null) ? ("." + loggerName) : "");
current = current.getParent();
}
// 拼裝出完整的配置鍵名, 用於從logging.properties中獲取值
logName = ContainerBase.class.getName() + "." + loggerName;
return logName;
}3. 兩類日誌
Tomcat中的日誌資訊被分為兩類，分別是：
1. 執行中的日誌。 它主要記錄執行的一些資訊，尤其是一些異常錯誤日誌資訊
2. 訪問日誌資訊。 它記錄訪問的時間、IP、訪問的資源等相關資訊。
接下來我們將分別針對這兩類資訊，探索下Tomcat內的相關實現類。
3.1 執行中的日誌
這類日誌最直接的例子就是Tomcat的啟動類BootStrap了。但凡是Tomcat中，只要涉及到使用log， 並且擁有如下欄位定義的，都是在記錄執行時日誌。
private static final org.apache.juli.logging.Log = org.apache.juli.logging.LogFactory.getLog(Xxxx.class);接下來我們就以上面這行程式碼為例，來進行一下稍微深入一些的探討。
沿著呼叫鏈， 經過幾次跳轉之後我們就會發現最終返回的Log實際型別為
DirectJDKLog。而跟蹤DirectJDKLog的建構函式就會發現其直接排程給了JDK的java.util.logging.Logger。這裡需要注意下的是
DirectJDKLog類的靜態建構函式塊，我們通過JVisualVM檢視發現java.util.logging.config.file不為空，而java.util.logging.config.class為空。所以這段靜態構造塊在Tomcat下預設是不會執行的。而涉及到 JDK中的
java.util.logging.Logger，必然逃不開LogManager。而按照上篇文章JDK研究之Logger的研究，在LogManager的靜態構造塊的邏輯裡，會查詢系統屬性java.util.logging.manager對應的值，如果發現不為空，則將其例項化作為LogManager的本次系統中的真正實現者。 而我們可以從JVISUALVM看到了這個鍵值對的。【下方截圖】所以現在讓我們看看
org.apache.juli.ClassLoaderLogManager； 其覆寫的readConfiguration方法，首先在當前的classLoader中查詢名為logging.properties的資源。如果當前classLoader中不存在會使用指定位置的logging.properties配置檔案。這裡就與我們上面解釋的logging.properties配置檔案讀取順序匹配上了。接下來的邏輯就回到了上面對配置檔案的解析，以及在Tomcat的諸多元件中，哪些元件用到了日誌元件，並且它們是如何使用的。
另外多提一句的是，我們在
org.apache.juli.logging.LogFactory的私有建構函式中發現，其使用了SPI來載入了 實現了org.apache.juli.logging.Log介面的自定義類。 所以我們是可以接管過來的。 注意建構函式必須有一個 String型別引數。（這是Tomcat8.x裡的邏輯）
3.2 訪問日誌資訊
此類日誌資訊預設是不輸出的，需要使用者主動進行配置。方式則是在Tomcat的配置檔案${catalina}/conf/server.xml中新增如下節點：
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs" pattern="%h %l %u %t "%r" %s %b" prefix="localhost_access_log." resolveHosts="false" suffix=".txt"/>於是我們的關注點順勢就來到了這個AccessLogValve上。
關於這個AccessLogValve類，這次我們的關注點主要是如下這些：
1. 其間接實現了Lifecycle介面，並且覆寫了startInternal方法。而自定義的startInternal邏輯會按照既定的日誌檔名規則，生成一個存放訪問日誌的日誌檔案並將該檔案開啟，準備寫入。所以我們平時在啟動完畢Tomcat之後，發現日誌檔案已經生成，並且無法刪除。
2. 其直接實現了AccessLog介面。按照這個介面上的註釋說明，這是Tomcat內部使用的介面，繼承自該介面則表明該Valve將提供記錄訪問日誌的功能，而且有個比較重要的點是，該介面的實現Valve還能記錄被拒絕訪問的請求。
3. 內部有個設計小技巧就是， 內部定義了一個介面 AccessLogElement， 需要記錄的特定資訊只需要繼承自該介面，實現自己的專有邏輯即可（例如SessionIdElement，RemoteAddrElement，CookieElement），最終的輸出的日誌就是這些實現類所記錄資訊的總和。
4. 其他相關類
Tomcat中與Log有關聯的類除了上面提到的AccessLogValve，ClassLoaderLogManager外，我們還可以關注以下相關類：
Container。 作為一個容器必須實現的介面，其契約了一個返回容器相關聯的Logger的getLogger方法，而預設的實現由ContainerBase完成，而且具體的容器實現類均未對此進行覆寫。另外還需要注意的是 其還定義了另外一個getAccessLog方法，用於記錄訪問日誌。甚至還有一個logAccess方法。ValveBase，作為Valve繼承鏈中關鍵的底層一環，其中定義了containerLog,這個用來獲取相關容器log的欄位。
5. 補充
最後我們來看看Tomcat啟動後，相應的JVM引數和系統引數。（以下截圖和資訊都是從JVisualVM中擷取而來的）
JVM引數
系統引數
awt.toolkit=sun.awt.windows.WToolkit
catalina.base=D:\apache-tomcat-8.0.33-windows-x64
catalina.home=D:\apache-tomcat-8.0.33-windows-x64
catalina.useNaming=true
common.loader="${catalina.base}/lib","${catalina.base}/lib/*.jar","${catalina.home}/lib","${catalina.home}/lib/*.jar"
file.encoding=GBK
file.encoding.pkg=sun.io
file.separator=\
java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment
java.awt.printerjob=sun.awt.windows.WPrinterJob
java.class.path=D:\apache-tomcat-8.0.33-windows-x64\bin\bootstrap.jar;D:\apache-tomcat-8.0.33-windows-x64\bin\tomcat-juli.jar
java.class.version=52.0
java.endorsed.dirs=D:\apache-tomcat-8.0.33-windows-x64\endorsed
java.ext.dirs=C:\Java\jdk1.8.0_92-64\jre\lib\ext;C:\Windows\Sun\Java\lib\ext
java.home=C:\Java\jdk1.8.0_92-64\jre
java.io.tmpdir=D:\apache-tomcat-8.0.33-windows-x64\temp
java.library.path=C:\Java\jdk1.8.0_92-64\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\ProgramData\Oracle\Java\javapath;C:\Program Files (x86)\Common Files\NetSarang;D:\apps\Oracle11\product\11.2.0\dbhome_1\bin;D:\apps\Oracle10\bin;C:\Program Files (x86)\Intel\iCLS Client\;C:\Program Files\Intel\iCLS Client\;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\Program Files (x86)\Common Files\Lenovo;C:\SWTOOLS\ReadyApps;D:\QuickStart;C:\Java\jdk1.8.0_92-64\bin;C:\Java\jdk1.8.0_92-64\jre\bin;E:\Java\_tools\apache-maven-3.3.3\bin;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Windows Kits\8.0\Windows Performance Toolkit\;C:\Program Files\Microsoft SQL Server\110\Tools\Binn\;E:\Java\_tools\gradle-1.6\bin;D:\apps\MySQL_Server_5.5\bin;;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\nodejs\node_global\;C:\Program Files\TortoiseSVN\bin;C:\Users\LQ\AppData\Local\Programs\Python\Python36-32\Scripts\;C:\Users\LQ\AppData\Local\Programs\Python\Python36-32\;C:\Program Files\Microsoft VS Code\bin;C:\Users\LQ\AppData\Roaming\npm;.
java.naming.factory.initial=org.apache.naming.java.javaURLContextFactory
java.naming.factory.url.pkgs=org.apache.naming
java.rmi.server.randomIDs=true
java.runtime.name=Java(TM) SE Runtime Environment
java.runtime.version=1.8.0_92-b14
java.specification.name=Java Platform API Specification
java.specification.vendor=Oracle Corporation
java.specification.version=1.8
java.util.logging.config.file=D:\apache-tomcat-8.0.33-windows-x64\conf\logging.properties
java.util.logging.manager=org.apache.juli.ClassLoaderLogManager
java.vendor=Oracle Corporation
java.vendor.url=http://java.oracle.com/
java.vendor.url.bug=http://bugreport.sun.com/bugreport/
java.version=1.8.0_92
java.vm.info=mixed mode
java.vm.name=Java HotSpot(TM) 64-Bit Server VM
java.vm.specification.name=Java Virtual Machine Specification
java.vm.specification.vendor=Oracle Corporation
java.vm.specification.version=1.8
java.vm.vendor=Oracle Corporation
java.vm.version=25.92-b14
line.separator=\r\n
os.arch=amd64
os.name=Windows 7
os.version=6.1
package.access=sun.,org.apache.catalina.,org.apache.coyote.,org.apache.jasper.,org.apache.tomcat.
package.definition=sun.,java.,org.apache.catalina.,org.apache.coyote.,org.apache.jasper.,org.apache.naming.,org.apache.tomcat.
path.separator=;
server.loader=
shared.loader=
sun.arch.data.model=64
sun.boot.class.path=C:\Java\jdk1.8.0_92-64\jre\lib\resources.jar;C:\Java\jdk1.8.0_92-64\jre\lib\rt.jar;C:\Java\jdk1.8.0_92-64\jre\lib\sunrsasign.jar;C:\Java\jdk1.8.0_92-64\jre\lib\jsse.jar;C:\Java\jdk1.8.0_92-64\jre\lib\jce.jar;C:\Java\jdk1.8.0_92-64\jre\lib\charsets.jar;C:\Java\jdk1.8.0_92-64\jre\lib\jfr.jar;C:\Java\jdk1.8.0_92-64\jre\classes
sun.boot.library.path=C:\Java\jdk1.8.0_92-64\jre\bin
sun.cpu.endian=little
sun.cpu.isalist=amd64
sun.desktop=windows
sun.io.unicode.encoding=UnicodeLittle
sun.java.command=org.apache.catalina.startup.Bootstrap start
sun.java.launcher=SUN_STANDARD
sun.jnu.encoding=GBK
sun.management.compiler=HotSpot 64-Bit Tiered Compilers
sun.os.patch.level=Service Pack 1
sun.stderr.encoding=ms936
sun.stdout.encoding=ms936
tomcat.util.buf.StringCache.byte.enabled=true
tomcat.util.scan.StandardJarScanFilter.jarsToScan=log4j-core*.jar,log4j-l*.jar,log4javascript*.jar
tomcat.util.scan.StandardJarScanFilter.jarsToSkip=bootstrap.jar,commons-daemon.jar,tomcat-juli.jar,annotations-api.jar,el-api.jar,jsp-api.jar,servlet-api.jar,websocket-api.jar,catalina.jar,catalina-ant.jar,catalina-ha.jar,catalina-storeconfig.jar,catalina-tribes.jar,jasper.jar,jasper-el.jar,ecj-*.jar,tomcat-api.jar,tomcat-util.jar,tomcat-util-scan.jar,tomcat-coyote.jar,tomcat-dbcp.jar,tomcat-jni.jar,tomcat-websocket.jar,tomcat-i18n-en.jar,tomcat-i18n-es.jar,tomcat-i18n-fr.jar,tomcat-i18n-ja.jar,tomcat-juli-adapters.jar,catalina-jmx-remote.jar,catalina-ws.jar,tomcat-jdbc.jar,tools.jar,commons-beanutils*.jar,commons-codec*.jar,commons-collections*.jar,commons-dbcp*.jar,commons-digester*.jar,commons-fileupload*.jar,commons-httpclient*.jar,commons-io*.jar,commons-lang*.jar,commons-logging*.jar,commons-math*.jar,commons-pool*.jar,jstl.jar,taglibs-standard-spec-*.jar,geronimo-spec-jaxrpc*.jar,wsdl4j*.jar,ant.jar,ant-junit*.jar,aspectj*.jar,jmx.jar,h2*.jar,hibernate*.jar,httpclient*.jar,jmx-tools.jar,jta*.jar,log4j*.jar,mail*.jar,slf4j*.jar,xercesImpl.jar,xmlParserAPIs.jar,xml-apis.jar,junit.jar,junit-*.jar,ant-launcher.jar,cobertura-*.jar,asm-*.jar,dom4j-*.jar,icu4j-*.jar,jaxen-*.jar,jdom-*.jar,jetty-*.jar,oro-*.jar,servlet-api-*.jar,tagsoup-*.jar,xmlParserAPIs-*.jar,xom-*.jar
user.country=CN
user.dir=D:\apache-tomcat-8.0.33-windows-x64\bin
user.home=C:\Users\LQ
user.language=zh
user.name=LQ
user.script=
user.timezone=Asia/Shanghai
user.variant=