2016年6月7日 星期二

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

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

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

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

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    <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。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    <?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 有被初始化，並且主程序持續執行即可。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    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 輸出。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    <?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 之間的不同，所以我在上面加了計數器以及一個隨機數字。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    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 輸出如下：

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    68
    69
    70
    71
    72
    73
    74
    75
    76
    77
    78
    79
    80
    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
    張貼者： 於
    標籤： ,

    沒有留言:

    張貼留言

    訂閱： 張貼留言 (Atom)