黑毛到白毛的攻城獅之路: SLF4J 與 Logback 的運作流程

最近因為工作需要，開始在研究如何自定義 logback 的 Appender
不過在開始嘗試實作之前，因為想要知道整個 slf4j 到 logback 等的整個執行流程為何
因此就做了這篇的簡單的研究。

SLF4J 與 Logback 的基礎架構

關於整個 SLF4J 與 Logback 的程式碼架構，可以參考下列的連結，有還不錯詳細的程式碼流程描述。

看完其實大略就能了解 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);
  }
}

            

        
      