Logback统一配置及环境变量加载问题

2019年6月9日 503次阅读来源: 曲水流觞TechRill

关键字: logback.xml in jar logback environment variable

最近实现了一下将logback.xml的配置统一在基础框架的jar包中，如此所有业务应用都不用关心日志的规范格式或者存放位置，只要做一下简单的配置即可。
对于logback.xml与log4j的兼容或者适配问题，本文不做详细讨论。
参见：Java日志框架slf4j、jcl、jul、log4j1、log4j2、logback大总结

1. logback.xml配置

基本上也是主流配置，几个特别说明的点：

格式化的输出说明

请参照 http://logback.qos.ch/manual/layouts.html

<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!
问题粗线了！现在看起来好像前面的第一种或者第二种方法才行得通了。。。这尼玛！

《Logback统一配置及环境变量加载问题》应用启动首次进入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>

    原文作者：曲水流觞TechRill
    原文地址: https://www.jianshu.com/p/39178af66aef
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。