自定義 Logback 的 Encoder

想要試著自定義一個可以產出 JSON 格式的 log
雖然之前已經有 PO 過 logstash 提供的 Encoder，就可以達到把 log 輸出成 JSON 的目的
不過基於某些無聊的理由，還是想要自己寫看看 XD。

什麼是 Encoder？

從 logback 官方文件 [1] 中，對於 Encoder 的簡易描述如下：

Encoders are responsible for transforming an event into a byte array as well as writing out that byte array into an OutputStream.

也就是說，Encoder 的責任，是將 log 的事件轉換成某種 byte 的表達形式，並且將其寫入到某個輸出用的串流。
而在我的目的中，我想要把 log 事件轉換成 JSON 的格式輸出
因此我該做的事情，就是把 log 事件的內容轉換成 JSON 格式，再把 JSON 格式的結果轉成 byte 送去給 OutputStream。

建立 GsonEncoder 的外皮

要開始時，先模仿別的開源專案 [2] 的 JacksonEncoder 的格式，做了一個 GsonEncoder
並且繼承 ch.qos.logback.core.spi.ContextAwareBase、實作 ch.qos.logback.core.encoder.Encoder<ILoggingEvent>。

public class GsonEncoder extends ContextAwareBase implements Encoder<iloggingevent> {}

這時編譯器就會通知需要實作某些方法，然後就會一口氣長出很多個 method。
於是…跳過一些小細節後（？！），GsonEncoder 就直接擴展成這樣了。

import java.io.IOException;
import java.io.OutputStream;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.encoder.Encoder;
import ch.qos.logback.core.spi.ContextAwareBase;

public class GsonEncoder extends ContextAwareBase implements Encoder<ILoggingEvent> {
    
    private boolean isStarted = false;

    public GsonEncoder () {
        System.out.println("GsonEncoder: constructor");
    }
    
    @Override
    public void init (OutputStream os) throws IOException {
        System.out.println("GsonEncoder: init()");
    }

    @Override
    public void doEncode (ILoggingEvent event) throws IOException {
        System.out.println("GsonEncoder: doEncode() - " + event);
    }

    @Override
    public void close() throws IOException {}

    @Override
    public void start() {
        this.isStarted = true;
    }

    @Override
    public void stop() {
        this.isStarted = false;
    }

    @Override
    public boolean isStarted() {
        return this.isStarted;
    }
}

到目前為止，只是單純加上了編譯器說需要加的 method，然後在裡面寫了一點 log。
至於為什麼要寫 log 呢？因為想快速了解 logback 在哪個階段是呼叫哪個 method，這樣可以比較快速地了解 method 的用途。
另外這裡的 log 是直接用 System.out 而不是用 Log Framework，是因為怕會形成無窮迴圈 XD。

為了要執行測試，因此當然需要放一個 main() 在某個地方：

public class App {
    private static Logger log = LoggerFactory.getLogger(App.class);
    
    public static void main(String[] args) {
        System.out.println("Main: I'm going to write a log.");
        log.info("Hello World!");
    }
}

除了負責寫一行 log 的 main() 以外，我們還需要一個 logback 設定檔，要求他必須使用剛剛建立的 GsonEncoder：

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
    <!-- Define the default standard out appender for outputing logs. -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="com.example.logtest.GsonEncoder" />
    </appender>

    <!-- Set the default logging level to "ALL" level for loggers which are 
        not specified. -->
    <root level="ALL">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

這設定檔也很簡單，就是要求 Appender 要用預設的 ConsoleAppender，不過 Encoder 則要使用我剛剛建立的 GsonEncoder
除此之外什麼也不設定～（連輸出的格式也忽略了，反正現在使用的 Encoder 什麼事也不做）
然後，就可以快快樂樂地（？）開始執行了！XD
執行出來的結果如下：

15:34:57,848 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
15:34:57,848 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
15:34:57,848 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/java/workspace/logtest/target/classes/logback.xml]
15:34:57,929 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
15:34:57,931 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
GsonEncoder: constructor
GsonEncoder: init()
15:34:57,954 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
15:34:57,954 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
15:34:57,954 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
15:34:57,955 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@26f0a63f - Registering current configuration as safe fallback point
Main: I'm going to write a log.
GsonEncoder: doEncode() - [INFO] Hello World!

執行結果看得出來，doEncode() 就是最重要的寫入程序，Encoder 需要在 doEncode() 方法中具體描述該如何寫入 log。

植入 Charset 到 Encoder 的輸出

在正式開始準備 Encoder 之前，首先先解決一個小問題。
因為 JSON 格式的輸出依然會是一連串的字串，因此為了避免造成奇怪的困擾，最好先植入 Charset 到 Encoder 裡。

具體實作時，因為 [2] 的專案中已經有做了這些事情，因此可以直接沿用他們的成果
也就是讓 Encoder 繼承 org.eluder.logback.ext.core.CharacterEncoder<ILoggingEvent>。

public class GsonEncoder extends ContextAwareBase implements CharacterEncoder<ILoggingEvent> {
    private Charset charset = Charset.forName("UTF-8");

    ....(略)....

    @Override
    public void setCharset(Charset charset) {
        if (charset != null) {
            this.charset = charset;
        }
    }

    @Override
    public Charset getCharset() {
        return this.charset;
    }
}

從預設的 Encoder 改為繼承 CharacterEncoder 後，多了兩個需要實作的方法
除了實作這兩個方法以外，也加上變數紀錄目前的字元集，並且在初始化時預設使用 UTF-8 字元集。

有了字元集以後，就要讓 doEncode() 在輸出時，指定使用這個字元集
這裡同時也多做了一點點事情，先把預定要用在輸出的 JSON 物件準備好，然後在要輸出時，指定以 charset 作為輸出的字元集。

public class GsonEncoder extends ContextAwareBase implements CharacterEncoder<ILoggingEvent> {
    private OutputStream outputStream = null;
    private JsonObject json = null;
    private Charset charset = Charset.forName("UTF-8");

    public GsonEncoder () {
        this.json = new JsonObject();
    }

    @Override
    public void init (OutputStream os) throws IOException {
        this.outputStream = os;
    }

    @Override
    public void doEncode (ILoggingEvent event) throws IOException {
        // Convert the JSON into string, and set the charset.
        byte[] bytes = this.json.toString().getBytes(this.getCharset());
        // Output the JSON string to the OutputStream.
        this.outputStream.write(bytes);
    }

    @Override
    public void close() throws IOException {
        this.outputStream.flush();
    }

    ....(略)....
}

接著再來執行看看，這次執行的結果會變這樣～。（PS. 原本測試結果的 System.out 在這個階段都先移除了）

17:15:58,458 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
17:15:58,458 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
17:15:58,458 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/java/workspace/logtest/target/classes/logback.xml]
17:15:58,538 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:15:58,541 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
17:15:58,571 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
17:15:58,571 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
17:15:58,572 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
17:15:58,574 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@470e2030 - Registering current configuration as safe fallback point
Main: I'm going to write a log.
{}

到這裡，可以看到最後一行顯示輸出的東西變成一個 JSON，但是是空的 JSON
不過這也是一如預期，畢竟上面的程式碼只有 new 了一個 JsonObject，卻從來沒有塞任何東西進去。
下個步驟，就要開始把 log 事件的內容塞進 JsonObject 了。

@Override
public void doEncode (ILoggingEvent event) throws IOException {
    // Convert the log event into JSON format.
    this.json.addProperty(
            "log_" + this.fieldNames.getLoggerName(), 
            event.getLoggerName());
    this.json.addProperty(
            "log_" + this.fieldNames.getLevel(), 
            event.getLevel().toString());
    this.json.addProperty(
            "log_" + this.fieldNames.getThreadName(), 
            event.getThreadName());
    this.json.addProperty(
            "log_" + this.fieldNames.getFormattedMessage(), 
            event.getFormattedMessage());
    this.json.addProperty(
            "log_" + this.fieldNames.getTimeStamp(), 
            event.getTimeStamp());
    this.json.addProperty(
            "log_" + this.fieldNames.getLevelValue(), 
            event.getLevel().levelInt);
        
    // Parse the MDC contents if there is any.
    Iterator<Entry<String, String>> mdcIter = 
            event.getMDCPropertyMap().entrySet().iterator();
    while (mdcIter.hasNext()) {
        Entry<String, String> mdcEntry = mdcIter.next();
        this.json.addProperty("mdc_" + mdcEntry.getKey(), mdcEntry.getValue());
    }
     
    // Convert the JSON into string, and set the charset.
    byte[] bytes = this.json.toString().getBytes(this.getCharset());
    // Output the JSON string to the OutputStream.
    this.outputStream.write(bytes);
}

然後執行時的輸出就會變這樣：

12:12:27,397 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
12:12:27,397 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
12:12:27,397 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/java/workspace/logtest/target/classes/logback.xml]
12:12:27,481 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
12:12:27,483 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
12:12:27,511 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
12:12:27,511 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
12:12:27,512 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
12:12:27,513 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@470e2030 - Registering current configuration as safe fallback point
Main: I'm going to write a log.
{"log_logger":"com.example.logtest.App","log_level":"INFO","log_thread":"main","log_formattedMessage":"Hello World!","log_timeStamp":1473307947515,"log_levelValue":20000}

到這裡，其實就已經可以看到 log 被正確地轉換成 JSON 格式輸出了。

參考資料

1. Chapter 5: Encoders
2. logback-ext