1. 程式人生 > >Logback統一配置及環境變數載入問題(zookeeper)

Logback統一配置及環境變數載入問題(zookeeper)

最近實現了一下將logback.xml的配置統一在基礎框架的jar包中,如此所有業務應用都不用關心日誌的規範格式或者存放位置,只要做一下簡單的配置即可。
對於logback.xml與log4j的相容或者適配問題,本文不做詳細討論。
參見:Java日誌框架slf4j、jcl、jul、log4j1、log4j2、logback大總結

1. logback.xml配置

基本上也是主流配置,幾個特別說明的點:

格式化的輸出說明

<b>片段</b>:
%20logger false 20 none Left pad with spaces if the logger name is less than 20 characters long.
%-20logger true 20 none Right pad with spaces if the logger name is less than 20 characters long.
%.30logger NA none 30 Truncate from the beginning if the logger name is longer than 30 characters.
%20.30logger false 20 30 Left pad with spaces if the logger name is shorter than 20 characters. However, if logger name is longer than 30 characters, then truncate from the beginning.
%-20.30logger true 20 30 Right pad with spaces if the logger name is shorter than 20 characters. However, if logger name is longer than 30 characters, then truncate from the beginning.
%.-30logger NA none 30 Truncate from the end if the logger name is longer than 30 characters.

%d表示日期,
%thread: 表示執行緒名
%level:日誌級別
%msg:日誌訊息
%logger: Java類名(含包名,這裡設定了36位,若超過36位,包名會精簡為類似a.b.c.JavaBean)
%line: Java類的行號

NEUTRAL使用

因為正常日誌和錯誤異常日誌是拆分成兩個檔案的,所以在appender=FILE中如果使用ThresholdFilter配置的level是最低閥值(一般是INFO),
ERROR也會進入到sys.log中,這時需要將ERROR過濾掉,設定Match Error 直接DENY, Mismatch Error則Neutral中立繼續走下面的filter。

環境變數的使用

這裡配置了大量的環境變數,比如log.path(日誌的路徑),app.name(應用名稱),log.root.level(日誌root級別)等,
這些變數若在每個業務系統的本地,可以基於maven的profile filter resources進行變數替換即可,
但是當前的設計是想將logback.xml放在一個公共元件的jar包內, 這個maven是無法替換jar包內檔案的內容的。引申出我們下面的實現。
(當然你可以使用一些maven plugin進行unzip,修改後再zip一把,實在太麻煩 >_<!)

<configuration>
    <!--<statusListener class="ch.qos.logback.core.status.NopStatusListener" />-->
    <jmxConfigurator/>
    
    <!-- 控制檯輸出 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>
                [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%-36.36thread] [%-5level] [%-36.36logger{36}:%-4.4line] - %msg%n
            </pattern>
        </encoder>
    </appender>
    <!-- 按照每天生成日誌檔案 -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/${app.name}/sys.log</file>
        <!--拒絕ERROR日誌-->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>DENY</onMatch>
            <onMisMatch>NEUTRAL</onMisMatch>
        </filter>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>${log.lowest.level}</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${log.path}/${app.name}/sys-%d{yyyy-MM-dd}-%i.log</FileNamePattern>
            <MaxHistory>90</MaxHistory>
            <TimeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <MaxFileSize>10MB</MaxFileSize>
            </TimeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>
                [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%-36.36thread] [%-5level] [%-36.36logger{36}:%-4.4line] - %msg%n
            </pattern>
        </encoder>
    </appender>
    <appender name="FILE-ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/${app.name}/sys-err.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${log.path}/${app.name}/sys-err-%d{yyyy-MM-dd}-%i.log</FileNamePattern>
            <MaxHistory>90</MaxHistory>
            <TimeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <MaxFileSize>10MB</MaxFileSize>
            </TimeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%-36.36thread] [%-5level] [%-36.36logger{36}:%-4.4line] - %msg%n
            </pattern>
        </encoder>
    </appender>

    <!-- show parameters for hibernate sql 專為 Hibernate 定製 -->
    <logger name="org.hibernate.type.descriptor.sql.BasicBinder"    additivity="true" level="${log.hibernate.level}" />
    <logger name="org.hibernate.type.descriptor.sql.BasicExtractor" additivity="true" level="${log.hibernate.level}" />
    <logger name="org.hibernate.SQL"                                additivity="true" level="${log.hibernate.level}" />
    <logger name="org.springframework"                              additivity="true" level="${log.spring.level}"/>
    <logger name="com.myown"                                        additivity="true" level="${log.root.level}"/>

    <!-- 日誌輸出級別 -->
    <root level="${log.root.level}">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE"/>
        <appender-ref ref="FILE-ERROR"/>
    </root>

</configuration>

2. web.xml 監聽器的實現

上面logback.xml裡設定了大量的環境變數,而這些環境變數都必須在Web應用啟動之前設定完畢。
實現方式其實比較多:
a. 第一種: 設定JVM的啟動引數 -Dlog.path=/logs/app/ -Dlog.root.level=INFO
b. 第二種:設定應用伺服器的啟動引數,比如tomcat,在bin資料夾下新增一個bat(windows)或者shell檔案(linux),命名為setenv.bat/sh,

setenv.bat內容:
set log.path=/usr/local/src/logs/test
set log.root.level=INFO
....

c. 第三種:前兩種處理方式都有些不妥的地方就是,開發人員pull程式碼之後無法直接部署tomcat執行,還需要新增setenv檔案,容易遺漏;
引數的設定不靈活:不能根據OS, 開發/測試/生產的環境變數動態調整log level或者log path。
(其實,在不同環境下的tomcat只要設定一次啟動引數,業務應用日後的部署都是一勞永逸的, 不排除以後採用第二種方案 _)
現,決定,通過監聽器來實現。

監聽器示例程式碼如下

public class LogbackListener implements ServletContextListener {
    @Override
    public void contextInitialized(ServletContextEvent event) {
        ServletContext sc = event.getServletContext();
        //新增系統屬性示例程式碼
        if (org.apache.commons.lang3.SystemUtils.IS_OS_WINDOWS) {
           System.setProperty("log.path", "${CATALINA_HOME}" + SystemUtils.FILE_SEPARATOR + "logs");
        } else {//linux
           System.setProperty("log.path", "/logs");
        }

        if (isProductEnv) {
           System.setProperty("log.root.level", "INFO");
        } else {//非生產環境
           System.setProperty("log.root.level", "DEBUG");
        } 

        ..........................

        WebLogbackConfigurer.initLogging(sc);
    }

    @Override
    public void contextDestroyed(ServletContextEvent event){
        WebLogbackConfigurer.shutdownLogging(event.getServletContext());
    }
}

web.xml新增監聽器配置,該監聽器的配置儘量位於第一位,至少保證在其他有可能使用日誌列印的監聽器之前。

············
<!--logback日誌環境變數配置-->
<listener>
    <listener-class>com.myown.framework.LogbackListener</listener-class>
</listener>
<!--Spring上下文-->
<listener>
    <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
</listener>
············

3. TOMCAT + JNDI + Druid連線池的坑

因為某個核心系統期望能監控一下資料庫連線方面的效能和請求情況,採用了開源連線池Druid, 在context.xml配置的jndi是這樣的:

 <!--
 1. tomcat lib需新增mysql驅動 mysql-connector-java-5.1.38.jar
     2. 新增 druid-1.0.16.jar
 3. filter若使用log4j,tomcat lib需新增log4j.jar;若使用slf4j基於logback,需新增slf4j-api-1.7.13.jar
 -->     
<Resource 
     name="jndi/nicholas"
     factory="com.alibaba.druid.pool.DruidDataSourceFactory"
     auth="Container"
     type="javax.sql.DataSource"
     driverClassName="com.mysql.jdbc.Driver"
     url="jdbc:mysql://127.0.0.1:3306/nicholas?useUnicode=true&characterEncoding=utf-8"
     username="root" 
     password="root"
     initialSize="10"
     minIdle="10"
     maxActive="50"
     maxWait="10000"    
     timeBetweenEvictionRunsMillis="60000" 
     minEvictableIdleTimeMillis="300000"
     removeabandoned="true" 
     removeabandonedtimeout="180"
     logabandoned="true"
     filters="stat,wall,slf4j"/>

具體druid的配置和使用就不詳談,注意最後的filters 配置了slf4j, 它的實現是基於web應用配置的logback,請看下圖首次進入LoggerContext的呼叫鏈情況。
其實此時的Tomcat啟動優先載入了druid jndi連線池,而druid又需要列印日誌,所以在我們的監聽器初始化之前, logback的配置已經載入完畢了,而載入的logback.xml中的一堆變數都是undefined!
問題粗線了!現在看起來好像前面的第一種或者第二種方法才行得通了。。。這尼瑪!

應用啟動首次進入LoggerContext的堆疊資訊

一個開源元件的依賴會帶來如此不堪忍受的問題,這個事件的教訓就是設計一個越基礎的元件越要減少對其他元件的依賴,不然會有各種升級或者相容層面的潛在隱患

目前本人的解決方案是在剛才的 LogbackListener 監聽器中重置logback上下文!

  @Override
  public void contextInitialized(ServletContextEvent event) {

    //系統環境變數設定 System.setProperty()
    ..............

    //進入Web之前判斷是否已載入了Logger,若已載入需要重置!
    if (loggerContext != null && loggerContext.getLoggerList().size() > 0) {
        //必須清空一下,否則之前載入的logger堆疊資訊還保留著StatusPrinter.print會打印出之前的狀態
        loggerContext.getStatusManager().clear();
        loggerContext.reset();
        ContextInitializer ci = new ContextInitializer(loggerContext);
        try {
            ci.autoConfig();
        } catch (JoranException e) {
            sc.log("-=-=-= Reset Logback status Failed =-=-=- \n" + ExceptionUtil.getStackTrace(e));
        }
    }

    WebLogbackConfigurer.initLogging(sc);
    StatusPrinter.print(loggerContext);
}

4. 預設賦值問題

某些情況下需要變數設定個預設值,以防出現比較噁心的 _IS_UNDEFINED 字尾( log4j不存在的變數會留空)
只要使用" :- " 操作符即可(冒號+減號)。
比如 log.path 沒有定義, 使用該變數的地方就會變成** log.path_IS_UNDEFINED**, 給他一個預設值

${log.path:-/var/logs/myapp}

5. 注意事項

Spring的WARN日誌無法打印出來

檢查spring是否exclude自帶的commons-logging 即 jcl jar包,並同時新增 jcl-over-slf4j的jar包,將其適配給slf4j

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-core</artifactId>
    <version>${spring.version}</version>
    <exclusions>
        <exclusion>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
</dependency>

Zookeeper/ZkClient等預設使用log4j的元件無法列印日誌

需要exclude log4j包,並新增log4j-over-slf4j依賴 (注意 slf4j-log4j12 與 log4j-over-slf4j的環形依賴會導致異常)

<dependency>
        <groupId>com.github.sgroschupf</groupId>
        <artifactId>zkclient</artifactId>
        <version>0.1</version>
        <exclusions>
            <exclusion>
                <groupId>log4j</groupId>
                <artifactId>log4j</artifactId>
            </exclusion>
        </exclusions>
 </dependency>
 <!--zkClient和disconf都會依賴zookeeper,而zookeeper會依賴slf4j-log4j12和log4j,
 在我們使用logback的情況下,需要將log4j轉為logback,則需依賴log4j-over-slf4j。
 slf4j-log4j12會與log4j-over-slf4j迴圈依賴導致衝突,
 所以所有依賴zookeeper的jar必須exclude掉slf4j-log4j12-->
<dependency>
    <groupId>org.apache.zookeeper</groupId>
    <artifactId>zookeeper</artifactId>
    <version>${zookeeper.version}</version>
    <exclusions>
        <exclusion>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
        </exclusion>
        <!--
        https://issues.apache.org/jira/browse/ZOOKEEPER-1371
        zookeeper Remove dependency on log4j in the source code.
        slf4j-log4j12會與log4j-over-slf4j迴圈依賴導致衝突
        -->
        <exclusion>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
</dependency>