叢集環境的 logging（一）：透過 slf4j + logback 集中化 log

在叢集環境中，應用程式往往會同時存在在很多個節點上
每個節點的 log 都各自輸出到自己的 console，或者可能輸出成某個檔案，但都四散在每個應用程式自己的節點上。
實務上如果想要觀察 log，通常會希望最起碼 log 可以集中到某個地方
這個需求，如果是使用 logback 作為 logging framework 時，可以透過使用 SocketAppender 和 Receiver 來達成。

在這個實驗範例中，目標是做出一個發送端、以及一個接收端
發送端自己不會輸出 log 到 Console 或者檔案等地方，而是會把 log 透過 Socket 輸出到接收端去
在接收端那邊則是自己不產生 log，只單純會把收到的 log 印到 Console 上。

不論是發送端還是接收端，在 Maven 的設定都是一致的，只需要引用 slf4j 和 logback 即可。

<dependencies>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.12</version>
        <scope>compile</scope>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.1.3</version>
        <scope>compile</scope>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>1.1.3</version>
        <scope>compile</scope>
    </dependency>
</dependencies>

接收端

接收端的 logback 設定

接收端這裡設定監聽 10000 port，然後輸出 log 到 Console。

<?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} | %logger{36} | %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" />
    </root>
    
    <receiver class="ch.qos.logback.classic.net.server.ServerSocketReceiver">
        <port>10000</port>
    </receiver>
</configuration>

接收端的程式碼

接收端這裡因為什麼事情都不做，所以其實只需要確保 logger 有被初始化，並且主程序持續執行即可。

public class App {
    public static void main(String[] args) {
        Logger log = LoggerFactory.getLogger("org.twgogo.jimwayne.logback.log_receiver");
        SecureRandom rand = new SecureRandom();
        log.info("Start log receiver.");
        
        while(true && !Thread.currentThread().isInterrupted()) {
            try {
                Thread.sleep(750 + rand.nextInt(500));
            } catch (InterruptedException e) {
                break;
            }
        }
    }
}

發送端

發送端的 logback 設定

發送端設定為發送到本機的 10000 port，並且不設定任何 Console 等 log 輸出。

<?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>

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

發送端的程式碼

發送端的程式碼需要定時一直發送 log，為了能夠分辨 log 之間的不同，所以我在上面加了計數器以及一個隨機數字。

public class App {
    public static void main(String[] args) {
        Logger log = LoggerFactory.getLogger("org.twgogo.jimwayne.logback");
        SecureRandom rand = new SecureRandom();
        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;
            }
        }
    }
}

執行結果

直接在 eclipse 上面執行時，不管是先打開接收端還是先打開發送端皆可
依序打開發送端、接收端、發送端、發送端時，eclipse 的 Console 輸出如下：

13:06:36,698 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
13:06:36,698 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
13:06:36,698 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/D:/java/workspace/log-receiver/target/classes/logback.xml]
13:06:36,750 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
13:06:36,763 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
13:06:36,768 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
13:06:36,826 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead.
13:06:36,826 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
13:06:36,826 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
13:06:36,826 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
13:06:36,826 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
13:06:36,827 |-INFO in ch.qos.logback.classic.joran.action.ReceiverAction - About to instantiate receiver of type [ch.qos.logback.classic.net.server.ServerSocketReceiver]
13:06:36,839 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
13:06:36,839 |-INFO in ch.qos.logback.classic.net.server.RemoteAppenderServerRunner@1517365b - listening on 0.0.0.0:10000
13:06:36,840 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4fccd51b - Registering current configuration as safe fallback point

2016-06-07 13:06:36,850 | o.t.jimwayne.logback.log_receiver | Start log receiver.
2016-06-07 13:06:39,263 | ch.qos.logback.classic.net.server | client 127.0.0.1:11585: connected
2016-06-07 13:06:39,287 | org.twgogo.jimwayne.logback | Start log sender.
2016-06-07 13:06:39,341 | org.twgogo.jimwayne.logback | Loop #1 for random number '2477088727250402193'.
2016-06-07 13:06:40,497 | org.twgogo.jimwayne.logback | Loop #2 for random number '4891991265883658464'.
2016-06-07 13:06:41,534 | ch.qos.logback.classic.net.server | client 127.0.0.1:11586: connected
2016-06-07 13:06:41,558 | org.twgogo.jimwayne.logback | Start log sender.
2016-06-07 13:06:41,609 | org.twgogo.jimwayne.logback | Loop #1 for random number '8115847070249619265'.
2016-06-07 13:06:41,680 | org.twgogo.jimwayne.logback | Loop #3 for random number '-2255591464725669199'.
2016-06-07 13:06:42,589 | org.twgogo.jimwayne.logback | Loop #4 for random number '2267715528372031940'.
2016-06-07 13:06:42,830 | org.twgogo.jimwayne.logback | Loop #2 for random number '5765601970248635947'.
2016-06-07 13:06:43,563 | org.twgogo.jimwayne.logback | Loop #5 for random number '-3540298563064490630'.
2016-06-07 13:06:43,987 | org.twgogo.jimwayne.logback | Loop #3 for random number '-5721848048489359168'.
2016-06-07 13:06:44,017 | ch.qos.logback.classic.net.server | client 127.0.0.1:11587: connected
2016-06-07 13:06:32,036 | org.twgogo.jimwayne.logback | Start log sender.
2016-06-07 13:06:32,091 | org.twgogo.jimwayne.logback | Loop #1 for random number '-3343572133399447841'.
2016-06-07 13:06:33,310 | org.twgogo.jimwayne.logback | Loop #2 for random number '8361756050527566939'.
2016-06-07 13:06:34,309 | org.twgogo.jimwayne.logback | Loop #3 for random number '2970066913998889016'.
2016-06-07 13:06:35,475 | org.twgogo.jimwayne.logback | Loop #4 for random number '1924958494255321900'.
2016-06-07 13:06:36,606 | org.twgogo.jimwayne.logback | Loop #5 for random number '-6889042668716761971'.
2016-06-07 13:06:37,738 | org.twgogo.jimwayne.logback | Loop #6 for random number '5720853347142455861'.
2016-06-07 13:06:38,832 | org.twgogo.jimwayne.logback | Loop #7 for random number '-1834532985886708488'.
2016-06-07 13:06:39,876 | org.twgogo.jimwayne.logback | Loop #8 for random number '-856392785877849549'.
2016-06-07 13:06:40,688 | org.twgogo.jimwayne.logback | Loop #9 for random number '7416494940671846526'.
2016-06-07 13:06:41,755 | org.twgogo.jimwayne.logback | Loop #10 for random number '3328274571658433936'.
2016-06-07 13:06:42,682 | org.twgogo.jimwayne.logback | Loop #11 for random number '8313105072737780128'.
2016-06-07 13:06:43,710 | org.twgogo.jimwayne.logback | Loop #12 for random number '-8431009685881524357'.
2016-06-07 13:06:44,473 | org.twgogo.jimwayne.logback | Loop #13 for random number '-7882929596084873730'.
2016-06-07 13:06:44,524 | org.twgogo.jimwayne.logback | Loop #6 for random number '4328657485118116621'.
2016-06-07 13:06:45,012 | org.twgogo.jimwayne.logback | Loop #4 for random number '4823841765909061686'.
2016-06-07 13:06:45,227 | org.twgogo.jimwayne.logback | Loop #14 for random number '-2269478587857810044'.
2016-06-07 13:06:45,737 | org.twgogo.jimwayne.logback | Loop #7 for random number '6963506672711810333'.
2016-06-07 13:06:46,248 | org.twgogo.jimwayne.logback | Loop #5 for random number '-1177335281158847218'.
2016-06-07 13:06:46,296 | org.twgogo.jimwayne.logback | Loop #15 for random number '-3101708605566184461'.
2016-06-07 13:06:46,672 | org.twgogo.jimwayne.logback | Loop #8 for random number '-5469215172432390199'.
2016-06-07 13:06:47,355 | org.twgogo.jimwayne.logback | Loop #6 for random number '-2107196439337531378'.
2016-06-07 13:06:47,482 | org.twgogo.jimwayne.logback | Loop #16 for random number '-1849023906357282931'.
2016-06-07 13:06:47,705 | org.twgogo.jimwayne.logback | Loop #9 for random number '-2019003416675370389'.
2016-06-07 13:06:48,391 | org.twgogo.jimwayne.logback | Loop #17 for random number '-4532999976520145333'.
2016-06-07 13:06:48,568 | org.twgogo.jimwayne.logback | Loop #7 for random number '7029604508806008720'.
2016-06-07 13:06:48,766 | org.twgogo.jimwayne.logback | Loop #10 for random number '1665689103860791508'.
2016-06-07 13:06:49,142 | org.twgogo.jimwayne.logback | Loop #18 for random number '-8619915223983954054'.
2016-06-07 13:06:49,619 | org.twgogo.jimwayne.logback | Loop #8 for random number '8748491928019320164'.
2016-06-07 13:06:49,637 | org.twgogo.jimwayne.logback | Loop #11 for random number '2651639384455619229'.
2016-06-07 13:06:49,904 | org.twgogo.jimwayne.logback | Loop #19 for random number '5043556708617774588'.
2016-06-07 13:06:50,593 | org.twgogo.jimwayne.logback | Loop #12 for random number '-7951897221620319884'.
2016-06-07 13:06:50,677 | org.twgogo.jimwayne.logback | Loop #20 for random number '9217459871678097751'.
2016-06-07 13:06:50,867 | org.twgogo.jimwayne.logback | Loop #9 for random number '1742540369436364124'.
2016-06-07 13:06:51,753 | org.twgogo.jimwayne.logback | Loop #10 for random number '7273951702299459387'.
2016-06-07 13:06:51,797 | org.twgogo.jimwayne.logback | Loop #13 for random number '-7307657874563917198'.
2016-06-07 13:06:51,900 | org.twgogo.jimwayne.logback | Loop #21 for random number '3696382657210380203'.
2016-06-07 13:06:52,568 | org.twgogo.jimwayne.logback | Loop #14 for random number '-5563830366198768554'.
2016-06-07 13:06:52,906 | org.twgogo.jimwayne.logback | Loop #11 for random number '-268409710790064830'.
2016-06-07 13:06:53,037 | org.twgogo.jimwayne.logback | Loop #22 for random number '-7252263550107496418'.
2016-06-07 13:06:53,455 | org.twgogo.jimwayne.logback | Loop #15 for random number '5234168803513887137'.
2016-06-07 13:06:53,826 | org.twgogo.jimwayne.logback | Loop #12 for random number '1341937088285992870'.
2016-06-07 13:06:53,833 | org.twgogo.jimwayne.logback | Loop #23 for random number '6872946259193988989'.
2016-06-07 13:06:54,380 | org.twgogo.jimwayne.logback | Loop #16 for random number '7032748767611170937'.
2016-06-07 13:06:54,658 | org.twgogo.jimwayne.logback | Loop #24 for random number '4850501335941002053'.
2016-06-07 13:06:54,871 | org.twgogo.jimwayne.logback | Loop #13 for random number '-6819622057190176553'.
2016-06-07 13:06:55,585 | org.twgogo.jimwayne.logback | Loop #17 for random number '321375362696603778'.
2016-06-07 13:06:55,705 | org.twgogo.jimwayne.logback | Loop #25 for random number '2122933895342882657'.
2016-06-07 13:06:55,988 | org.twgogo.jimwayne.logback | Loop #14 for random number '4479469529411464123'.
2016-06-07 13:06:56,350 | org.twgogo.jimwayne.logback | Loop #18 for random number '-5002713713227013483'.

從結果其實可以看得出來，一個接收端的確可以同時服務很多個發送端
並且 log 收集過來也可以依照自己喜歡的方式做重新格式化、定義輸出方法等等。
而發送端也有一定程度的本地端快取，在接收端暫時連接不到時，至少一定時間內還不會掉（詳細的相關設定可參考 [1]）。

參考資料

1. Chapter 4: Appenders
2. Chapter 14: Receivers