最近因為工作需要，開始在研究如何自定義 logback 的 Appender
不過在開始嘗試實作之前，因為想要知道整個 slf4j 到 logback 等的整個執行流程為何
因此就做了這篇的簡單的研究。
SLF4J 與 Logback 的基礎架構
關於整個 SLF4J 與 Logback 的程式碼架構，可以參考下列的連結，有還不錯詳細的程式碼流程描述。
- 读logback源码系列文章（一）——对接slf4j
- 读logback源码系列文章（二）——提供ILoggerFactory
- 读logback源码系列文章（三）——创建Logger
- 读logback源码系列文章（四）——记录日志
- 读logback源码系列文章（五）——Appender
- 读logback源码系列文章（六）——ContextInitializer
- 读logback源码系列文章（七）——配置的实际工作类Action
- 读logback源码系列文章（八）——记录日志的实际工作类Encoder
看完其實大略就能了解 Logback 大概是如何運作的了。
不過這裡我還是對於設定檔如何對照到 Appender 的過程覺得不太了解，所以就繼續做了下面的事情來確認。
追蹤 SLF4J 與 Logback 的初始化流程
這裡我是下載了一個能夠把 log 輸出到 AWS DynamoDB 的開源專案 [1]，並且實際嘗試執行，來觀察整個程式的流程。
首先，先故意放了不完整的 logback 設定檔，意圖讓 SLF4J 與 logback 在初始化時發生錯誤
就可以從 stack trace 的紀錄，大略看出整個初始化時，是透過什麼樣的流程在讀取設定的。
以下是 logback.xml 的內容：
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<!-- Define the default standard out appender for outputing logs. -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{ISO8601} | %-5level | %logger{36} [%thread] | %msg%n
</Pattern>
</layout>
</appender>
<appender name="DYNAMO" class="org.eluder.logback.ext.dynamodb.appender.DynamoDbAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%d{ISO8601} | %-5level | %logger{36} [%thread] | %msg%n
</Pattern>
</layout>
</appender>
<!-- Set the default logging level to "ALL" level for loggers which are
not specified. -->
<root level="ALL">
<appender-ref ref="STDOUT" />
<appender-ref ref="DYNAMO" />
</root>
</configuration>
上述的設定檔，就是指定除了標準的 Console 以外，還要把 log 輸出到 DynamoDB 上。
不過正常要輸出到 DynamoDB 上，必須要提供包含 region、access key、access credential 等等的資訊
否則理論上 Appender 應該根本沒有權限可以寫入任何東西。
而上述設定檔中，完全沒有寫上這些資訊
因此預期程式應該會在初始化階段時，會遭遇 DynamoDbAppender 需要的參數沒有被設定的 Exception。
實際執行後，程式噴出了以下的錯誤訊息：
14:46:49,005 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@16:13 - RuntimeException in Action for tag [appender] java.lang.IllegalArgumentException: No region provided at java.lang.IllegalArgumentException: No region provided at at com.amazonaws.AmazonWebServiceClient.setRegion(AmazonWebServiceClient.java:364) at at org.eluder.logback.ext.dynamodb.appender.DynamoDbAppender.doStart(DynamoDbAppender.java:107) at at org.eluder.logback.ext.aws.core.AbstractAwsEncodingStringAppender.start(AbstractAwsEncodingStringAppender.java:123) at at org.eluder.logback.ext.dynamodb.appender.DynamoDbAppender.start(DynamoDbAppender.java:97) at at ch.qos.logback.core.joran.action.AppenderAction.end(AppenderAction.java:96) at at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:317) at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:196) at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:182) at at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99) at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49) at at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77) at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152) at at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85) at at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55) at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141) at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120) at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331) at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283) at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:304) at at com.example.logtest.App.<clinit>(App.java:7)
上述的錯誤訊息表明了需要設定 region，這部份完全一如預期。
而從這段 stack trace 可以看出，整個程式在初始化時，會從 joran [2] 讀取設定檔，並且也在這個階段嘗試解析設定檔
最後會呼叫指定的 Appender 的 start() 方法，讓 Appender 自行進行自己的初始化程序。
追蹤 Logback 如何讀取設定檔
上述的 stack trace 繼續往下追查時，會發現造成錯誤的 region 並沒有看到在何時被設定的
因此估計要往前追查 joran 的執行程序，才能看到它是如何決定要把設定檔裡的參數餵給 Appender 吧。
首先，先看到 ch.qos.logback.classic.util.ContextInitializer.configureByResource 這段的程式碼
可以看到下述的內容：
public void configureByResource(URL url) throws JoranException {
if (url == null) {
throw new IllegalArgumentException("URL argument cannot be null");
}
final String urlString = url.toString();
if (urlString.endsWith("groovy")) {
if (EnvUtil.isGroovyAvailable()) {
// avoid directly referring to GafferConfigurator so as to avoid
// loading groovy.lang.GroovyObject . See also http://jira.qos.ch/browse/LBCLASSIC-214
GafferUtil.runGafferConfiguratorOn(loggerContext, this, url);
} else {
StatusManager sm = loggerContext.getStatusManager();
sm.add(new ErrorStatus("Groovy classes are not available on the class path. ABORTING INITIALIZATION.",
loggerContext));
}
} else if (urlString.endsWith("xml")) {
JoranConfigurator configurator = new JoranConfigurator();
configurator.setContext(loggerContext);
configurator.doConfigure(url);
} else {
throw new LogbackException("Unexpected filename extension of file [" + url.toString() + "]. Should be either .groovy or .xml");
}
}
這裡就能看到跟 logback 文件 [3] 差不多的程序，也就是 logback 會先嘗試尋找 logback.groovy
如果找不到的話，就會接著找 logback-test.xml、logback.xml 等。
而這次實驗中的狀況，是他應該要找到 logback.xml。
註：更精確來說，應該往前看到 ch.qos.logback.classic.util.ContextInitializer.autoConfig()
那段程式碼中呼叫的 findURLOfDefaultConfigurationFile(true)，就是在做尋找預設的設定檔的事情
回傳值就是被找到的設定檔的 URL。
這裡看到的 configurator.doConfigure(url)，url 表示的是設定檔的路徑
因此這段程式碼接下來要做的事情，應該就是解析 XML 內容了。
繼續往下追查時，可以看到下述這段程式碼：
public final void doConfigure(final InputSource inputSource)
throws JoranException {
long threshold = System.currentTimeMillis();
if (!ConfigurationWatchListUtil.wasConfigurationWatchListReset(context)) {
informContextOfURLUsedForConfiguration(getContext(), null);
}
SaxEventRecorder recorder = new SaxEventRecorder(context);
recorder.recordEvents(inputSource);
doConfigure(recorder.saxEventList);
// no exceptions a this level
StatusUtil statusUtil = new StatusUtil(context);
if (statusUtil.noXMLParsingErrorsOccurred(threshold)) {
addInfo("Registering current configuration as safe fallback point");
registerSafeConfiguration();
}
}
這裡的輸入參數是 InputSource，是前兩個 doConfigure() 呼叫時做的結果
把設定檔的 URL 讀取成 InputStream，再轉換成 InputSource 的型態，如此一來就可以使用 SAX 來做 XML 內容解析。
從上述程式碼的第 8~9 行，就開始真正地去解析 XML 內容
最後解析完的內容，應該是被存進 recorder.saxEventList 這個清單裡了。
取得 Event 清單後，接著第 10 行的 doConfigure(recorder.saxEventList)，把 Event List 繼續往後傳遞。
接著…卡住了 XD
思考了一段時間，想說也許試試別的方向。因此就先試著在 DynamoDbAppender 的 setRegion(String region) 上加入例外
意圖讓程式執行到 setRegion() 時，能夠印出 stack trace。最後印出來的 stack trace 如下：
java.lang.Exception at org.eluder.logback.ext.dynamodb.appender.DynamoDbAppender.setRegion(DynamoDbAppender.java:78) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at ch.qos.logback.core.joran.util.PropertySetter.setProperty(PropertySetter.java:168) at ch.qos.logback.core.joran.util.PropertySetter.setProperty(PropertySetter.java:120) at ch.qos.logback.core.joran.action.NestedBasicPropertyIA.body(NestedBasicPropertyIA.java:92) at ch.qos.logback.core.joran.spi.Interpreter.callBodyAction(Interpreter.java:295) at ch.qos.logback.core.joran.spi.Interpreter.characters(Interpreter.java:175) at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:57) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:149) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:135) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:99) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:49) at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:77) at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:152) at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85) at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55) at org.slf4j.LoggerFactory.bind(LoggerFactory.java:141) at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:120) at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:331) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:283) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:304) at com.example.logtest.App.<clinit>(App.java:7)
從前面的 stack trace，只能看出後續有個迴圈在尋訪 XML，但 StartEvent、BodyEvent 跟 EndEvent 各自是什麼都看不出來。
但這段 stack trace 綜合起來看的話，可以看到這裡呼叫了 ch.qos.logback.core.joran.spi.Interpreter.callBodyAction()
也就是說，在呼叫 setRegion() 時，interpreter 正在執行 callBodyAction()
因此可以判斷 BodyEvent 表示的，應該是設定檔上的 XML element 內容。
繼續往後看，在 callBodyAction() 之後，就會到了 setProperty() 方法，這裡就是真正把 XML 的內容設定給 Appender 的部份了。
而實際上執行的方式，是透過 java.beans.PropertyDescriptor [4-5] 來進行的。
public void setProperty(PropertyDescriptor prop, String name, String value)
throws PropertySetterException {
Method setter = prop.getWriteMethod();
if (setter == null) {
throw new PropertySetterException("No setter for property [" + name
+ "].");
}
Class<?>[] paramTypes = setter.getParameterTypes();
if (paramTypes.length != 1) {
throw new PropertySetterException("#params for setter != 1");
}
Object arg;
try {
arg = StringToObjectConverter.convertArg(this, value, paramTypes[0]);
} catch (Throwable t) {
throw new PropertySetterException("Conversion to type [" + paramTypes[0]
+ "] failed. ", t);
}
if (arg == null) {
throw new PropertySetterException("Conversion to type [" + paramTypes[0]
+ "] failed.");
}
try {
setter.invoke(obj, arg);
} catch (Exception ex) {
throw new PropertySetterException(ex);
}
}
另外，後來發現其實前面給的讀源碼系列的文章裡，也有講到這段設定檔讀取的步驟
只是因為我一開始是跳著看的，所以完全跳過那篇沒看到 XD
可以參考 读logback源码系列文章（六）——ContextInitializer。
沒有留言:
張貼留言