黑毛到白毛的攻城獅之路: 叢集環境的 logging（二）：辨識集中化 log 的來源

在前篇文章中，利用了 logback 的 SocketAppender 和 Receiver 功能，將不同來源的 logs 集中到一個地方
但在沒有特別設計的情況下，其實我們通常會分不出來哪個 log 來自哪裡。
不過這個問題在 logback 裡已經被考慮過了，可以利用 Mapped Diagnostic Context [1-2] 來實現。

在處理接收端與發送端之前，首先需要雙方先講好參數為何
因為 Mapped Diagnostic Context 概念上有點像是幫 log 上標籤，標籤為何是任意定義的
因此雙方要先講好標籤是什麼，這樣才能正確地讓標籤輸出。

在這個例子中，假設要送的標籤是 “hostname”，用來表示主機名稱。

接收端

接收端主要要做的事情，就是在輸出的設定上面加上輸出標籤，讓最後看到的 log 能分得出是來自哪個發送端。

接收端的 logback 設定檔

<?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>%X{hostname} | %d{ISO8601} | %msg%n</Pattern>
        </layout>
    </appender>
    
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>centralized-logs.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- hourly rollover -->
            <fileNamePattern>centralized-logs.%d{yyyy-MM-dd_HH}.gz</fileNamePattern>
            <!-- keep 3 days' worth of history -->
            <maxHistory>3</maxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <charset>UTF-8</charset>
            <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%X{hostname} | %d{ISO8601} | %-5level | %logger{36} [%thread] | %msg%n</Pattern>
        </layout>
        </encoder>
    </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="FILE" />
    </root>
    
    <receiver class="ch.qos.logback.classic.net.server.ServerSocketReceiver">
        <port>10000</port>
    </receiver>
</configuration>

跟原本前篇文章中的接收端的設定，差別在於 <Pattern> 標籤裡多了 %X{hostname} 這個表示式。
這個表示式就是在指定要輸出名字是 hostname 的 context。
至於到底要怎麼設定這個 context，就要看接下來的發送端了。

發送端

發送端要做兩件事，第一個是要設定 context，並且名稱必須是 hostname。
第二個則是要增加除了 SocketAppender 以外的另一個 Appender，原因可以參考 [3]
因為 logback 至少到現在為止還有一個 bug，如果只有使用 SocketAppender 的話，會導致 MDC 不會發生效用
因此必須為了繞過這個 bug，在 log 設定中增加其他的 Appender。

發送端的 logback 設定檔

要增加任意一種 Appender，其實隨便什麼都可以，直接用 ConsoleAppender 是最簡單的。
不過在這個範例裡面，因為我是直接看接收端的 ConsoleAppender 輸出，所以必須讓發送端用別的 Appender
因此就先給他用 RollingFileAppender 了。
另外這只是從別的專案隨便貼過來的 RollingFileAppender，其實也不用刻意寫得這麼複雜 XD
重點只是要有第二個 Appender 而已。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="SOCKET" class="ch.qos.logback.classic.net.SocketAppender">
        <remoteHost>localhost</remoteHost>
        <port>10000</port>
        <reconnectionDelay>10000</reconnectionDelay>
        <includeCallerData>true</includeCallerData>
    </appender>
    
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- hourly rollover -->
            <fileNamePattern>logs.%d{yyyy-MM-dd_HH}.gz</fileNamePattern>
            <!-- keep 3 days' worth of history -->
            <maxHistory>3</maxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <charset>UTF-8</charset>
            <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%X{hostname} | %d{ISO8601} | %-5level | %logger{36} [%thread] | %msg%n</Pattern>
        </layout>
        </encoder>
    </appender>

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

發送端的程式碼

發送端除了 logback 設定檔需要小改以外，還需要在程式碼裡面加上 MDC 的設定，也就是上面提到要雙邊講好的 “hostname”。

public class App {
    private static Logger log = LoggerFactory.getLogger("org.twgogo.jimwayne.logback");
    private static SecureRandom rand = new SecureRandom();
    static {
        try {
            MDC.put("hostname", InetAddress.getLocalHost().getHostName() + rand.nextInt());
        } catch (UnknownHostException e) {
            e.printStackTrace();
        }
    }
    
    public static void main(String[] args) {
        log.info("Start log sender.");
        
        long loopCount = 0;
        while(true && !Thread.currentThread().isInterrupted()) {
            log.info("Loop #{} for random number '{}'.", ++loopCount, rand.nextLong());
            
            try {
                Thread.sleep(750 + rand.nextInt(500));
            } catch (InterruptedException e) {
                log.warn("Thread is interrupted.", e);
                break;
            }
        }
    }
}

主要要做的就是第 6 行的 MDC.put()，要放入 hostname 這個標籤，並且依照實際狀況決定該怎麼辨識自己。
這個範例就直接用本機的主機名稱，串上一個隨機亂數了。

執行結果

執行結果如下：

17:18:45,341 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
17:18:45,341 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
17:18:45,341 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/java/workspace/log-receiver/target/classes/logback.xml]
17:18:45,392 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
17:18:45,405 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:18:45,410 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
17:18:45,467 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead.
17:18:45,467 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
17:18:45,467 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
17:18:45,467 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
17:18:45,469 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
17:18:45,480 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use gz compression
17:18:45,481 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern centralized-logs.%d{yyyy-MM-dd_HH} for the active file
17:18:45,484 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd_HH' from file name pattern 'centralized-logs.%d{yyyy-MM-dd_HH}.gz'.
17:18:45,484 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at the top of every hour.
17:18:45,486 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Jun 07 17:14:12 CST 2016
17:18:45,492 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: centralized-logs.log
17:18:45,492 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [centralized-logs.log]
17:18:45,493 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
17:18:45,493 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
17:18:45,493 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
17:18:45,494 |-INFO in ch.qos.logback.classic.joran.action.ReceiverAction - About to instantiate receiver of type [ch.qos.logback.classic.net.server.ServerSocketReceiver]
17:18:45,503 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
17:18:45,503 |-INFO in ch.qos.logback.classic.net.server.RemoteAppenderServerRunner@7a92922 - listening on 0.0.0.0:10000
17:18:45,503 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@71f2a7d5 - Registering current configuration as safe fallback point

 | 2016-06-07 17:18:45,512 | Start log receiver.
 | 2016-06-07 17:18:46,612 | client 127.0.0.1:14264: connected
localhost-31860410 | 2016-06-07 17:18:34,736 | Start log sender.
localhost-31860410 | 2016-06-07 17:18:34,738 | Loop #1 for random number '4730930752949837980'.
localhost-31860410 | 2016-06-07 17:18:35,810 | Loop #2 for random number '2569053911605338495'.
localhost-31860410 | 2016-06-07 17:18:36,696 | Loop #3 for random number '6250933723664553362'.
localhost-31860410 | 2016-06-07 17:18:37,671 | Loop #4 for random number '-6780645147676139207'.
localhost-31860410 | 2016-06-07 17:18:38,666 | Loop #5 for random number '279430208485883904'.
localhost-31860410 | 2016-06-07 17:18:39,470 | Loop #6 for random number '-5321056049219277523'.
localhost-31860410 | 2016-06-07 17:18:40,392 | Loop #7 for random number '-5567154954001836665'.
localhost-31860410 | 2016-06-07 17:18:41,422 | Loop #8 for random number '-4370911309192590370'.
localhost-31860410 | 2016-06-07 17:18:42,500 | Loop #9 for random number '7496533071806016424'.
localhost-31860410 | 2016-06-07 17:18:43,619 | Loop #10 for random number '1354905714454013878'.
localhost-31860410 | 2016-06-07 17:18:44,781 | Loop #11 for random number '7340945708771238259'.
localhost-31860410 | 2016-06-07 17:18:45,559 | Loop #12 for random number '-8291940781002401184'.
localhost-31860410 | 2016-06-07 17:18:46,426 | Loop #13 for random number '-6269973748325074423'.
localhost-31860410 | 2016-06-07 17:18:47,258 | Loop #14 for random number '5701371493355023211'.
localhost-31860410 | 2016-06-07 17:18:48,377 | Loop #15 for random number '5605983495404775257'.
localhost-31860410 | 2016-06-07 17:18:49,349 | Loop #16 for random number '2919129325065769249'.
localhost-31860410 | 2016-06-07 17:18:50,185 | Loop #17 for random number '-2348149095672186553'.
 | 2016-06-07 17:18:50,780 | client 127.0.0.1:14266: connected
localhost1272909563 | 2016-06-07 17:18:38,899 | Start log sender.
localhost1272909563 | 2016-06-07 17:18:38,901 | Loop #1 for random number '-287632790859998126'.
localhost1272909563 | 2016-06-07 17:18:39,924 | Loop #2 for random number '-2209376649110257313'.
localhost1272909563 | 2016-06-07 17:18:41,009 | Loop #3 for random number '5216300361498021617'.
localhost1272909563 | 2016-06-07 17:18:42,073 | Loop #4 for random number '-5256360638002134492'.
localhost1272909563 | 2016-06-07 17:18:42,914 | Loop #5 for random number '-957587702714683813'.
localhost1272909563 | 2016-06-07 17:18:43,817 | Loop #6 for random number '-2880884466318472135'.
localhost1272909563 | 2016-06-07 17:18:44,962 | Loop #7 for random number '-9022708325609562498'.
localhost1272909563 | 2016-06-07 17:18:46,016 | Loop #8 for random number '-3855751112245364474'.
localhost1272909563 | 2016-06-07 17:18:46,895 | Loop #9 for random number '7781759774216639721'.
localhost1272909563 | 2016-06-07 17:18:47,904 | Loop #10 for random number '-2894264696776239715'.
localhost1272909563 | 2016-06-07 17:18:48,782 | Loop #11 for random number '-8403973080714369475'.
localhost1272909563 | 2016-06-07 17:18:49,547 | Loop #12 for random number '-6041127791393145966'.
localhost1272909563 | 2016-06-07 17:18:50,509 | Loop #13 for random number '-155553052844135922'.
localhost-31860410 | 2016-06-07 17:18:51,427 | Loop #18 for random number '-421002592523447016'.
localhost1272909563 | 2016-06-07 17:18:51,495 | Loop #14 for random number '-3204305905996718491'.
localhost-31860410 | 2016-06-07 17:18:52,439 | Loop #19 for random number '-942557067622215989'.
localhost1272909563 | 2016-06-07 17:18:52,490 | Loop #15 for random number '-3930246573917277686'.
localhost-31860410 | 2016-06-07 17:18:53,590 | Loop #20 for random number '-7107904602548912680'.
localhost1272909563 | 2016-06-07 17:18:53,602 | Loop #16 for random number '7690956253126484337'.
localhost1272909563 | 2016-06-07 17:18:54,551 | Loop #17 for random number '-3718298670671143900'.
localhost-31860410 | 2016-06-07 17:18:54,805 | Loop #21 for random number '-3186941869535552233'.
localhost1272909563 | 2016-06-07 17:18:55,566 | Loop #18 for random number '7174452634540933599'.
localhost-31860410 | 2016-06-07 17:18:55,748 | Loop #22 for random number '-9101650415748728539'.
localhost1272909563 | 2016-06-07 17:18:56,338 | Loop #19 for random number '-4866865173157258845'.
localhost-31860410 | 2016-06-07 17:18:56,732 | Loop #23 for random number '-8900425140489076357'.
localhost1272909563 | 2016-06-07 17:18:57,412 | Loop #20 for random number '-874909555949673837'.
localhost-31860410 | 2016-06-07 17:18:57,577 | Loop #24 for random number '-4067005719438763625'.
localhost1272909563 | 2016-06-07 17:18:58,277 | Loop #21 for random number '1002261501288858375'.
localhost-31860410 | 2016-06-07 17:18:58,645 | Loop #25 for random number '-7740754626700862375'.
localhost-31860410 | 2016-06-07 17:18:59,504 | Loop #26 for random number '-5552203376652119240'.

從結果會看到，後半段多數的 log 前面會多出 “localhost-31860410” 或者 “localhost1272909563”
這就是從兩個不同的發送端送出的 log。
而裡面有幾個看起來是第一欄沒有內容的 log，就是接收端自己的 log
因為在上面的流程中，我並沒有在接收端這邊做 MDC.put() 的動作，因此接收端這邊自己產生的 log 沒有 hostname 這個值。

黑毛到白毛的攻城獅之路

2016年6月7日星期二

叢集環境的 logging（二）：辨識集中化 log 的來源

接收端

接收端的 logback 設定檔

發送端

發送端的 logback 設定檔

發送端的程式碼

執行結果

參考資料

沒有留言:

張貼留言

2016年6月7日 星期二

叢集環境的 logging（二）：辨識集中化 log 的來源

接收端

接收端的 logback 設定檔

發送端

發送端的 logback 設定檔

發送端的程式碼

執行結果

參考資料

沒有留言:

張貼留言

2016年6月7日星期二