Logback(6) 实战

我们在前面5篇logback的介绍中学习了logback配置知识，现在我们用一个项目来实战一下我们的学习成果吧。

前阵子我用elastic-job搭建了一个简单的push练手项目，基于Spring搭建。

github：https://github.com/fzustone/push

这个项目缺了日志相关的配置，那今天我们就来补全它。首先我们先明确一下我们的的需求：

1. 测试环境需要控制台输出，生产环境输出到文件；
2. 日志需要归档。比如按照每天进行一次归档；
3. 要有主日志与错误日志。为了方便运维快速定位错误，要把错误的日志单独打印到一个日志中；
4. 分job打印日志。作为推送项目，可能存在多个job，如果这些job都打在一份日志显然会很乱，需要区分打印。

接下来我们根据上面的需求一步一步来解决：

不同环境不同的配置文件

我们在之前学习的时候知道了logback配置文件有自己的加载顺序

1. logback 会在类路径下寻找名为 logback-test.xml 的文件。
2. 如果没有找到，logback 会继续寻找名为 logback.groovy 的文件。
3. 如果没有找到，logback 会继续寻找名为 logback.xml 的文件。
4. 如果没有找到，将会通过 JDK 提供的 ServiceLoader 工具在类路径下寻找文件 META-INFO/services/ch.qos.logback.classic.spi.Configurator，该文件的内容为实现了 Configurator 接口的实现类的全限定类名。
5. 如果以上都没有成功，logback 会通过 BasicConfigurator 为自己进行配置，并且日志将会全部在控制台打印出来。

那我们这里可以在开发环境新建一个 logback-test.xml 配置文件，用于在开发环境的调试，再新建一份logback.xml用于线上的配置。在代码打包的时候不把 logback-test.xml 配置文件打到包里。不过现在很多公司都用上了devops，可以很方便直接替换配置文件。这里我们不多做赘述。

日志归档

为了实现日志归档，我们知道需要用RollingFileAppender,我们又想要按照天粒度的规则进行归档，那就需要TimeBasedRollingPolicy策略帮我们实现。

<!--滚动文件-->
<appender name="infoRollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
   <file>push-info.log</file>
   <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${LOG_HOME}/push-info.%d{yyyy-MM-dd}.log</fileNamePattern>
      <!--保存最近30天的日志-->
      <maxHistory>30</maxHistory>
   </rollingPolicy>
   <encoder>
      <charset>UTF-8</charset>
      <pattern>${LOG_PATTERN}</pattern>
   </encoder>
</appender>

这里我们看到了${LOG_HOME}、${LOG_PATTERN}不难看出这是一个变量，想要使用变量我们需要使用property。

<property name="LOG_HOME" value="backup"/>

<property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread]  [%X{jobName}] %logger{0} %msg%n"/>

至此我们就拥有了一个可以按天归档轮转的appender。

主日志与错误日志

想要主日志简单，我们把上面的appender放置到root logger下即可，那么如何得到错误日志，很显然啊要用上我们的过滤器，这里只涉及到日志等级是否打印，所以用常规过滤器即可，我们这里使用了ThresholdFilter临界值过滤器，将低于error等级的日志全部过滤。

<appender name="errorRollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>push-error.log</file>
        <!-- ThresholdFilter:临界值过滤器，过滤掉 TRACE 和 DEBUG 级别的日志 -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>error</level>
        </filter>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/push-error.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory><!--保存最近30天的日志-->
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
</appender>

分job打印日志

这就迎来了我们的一个难点！上面的所有操作均为所有日志一箩筐全打印，那么我想要把我真正的业务job一个个拆开记录日志怎么办呀？

我们先搜索一下logback有没有比较合适的appender可以做这个事情呢？还真有！那就是SiftingAppender

对于Logback委托给它的日志事件，SiftingAppender会对日志事件做一些区分，然后不同的事件SiftingAppender会委托不同的appender去完成真正的写操作。

我们打开SiftingAppender这个类，可以发现他自身有一个默认的discriminator是MDCBasedDiscriminator，当然你也可以自定义一个discriminator。通过discriminator进行区分不同的事件，用不同的appender进行处理日志事件。

来具体看下我们是怎么做的

    <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
        <!--discriminator鉴别器，根据MDC这个key对应的value鉴别日志事件，然后委托给具体appender写日志-->
        <discriminator>
            <key>jobName</key>
            <defaultValue>head0</defaultValue>
        </discriminator>
        <sift>
            <appender name="File-${jobName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>jobs/${jobName}.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <fileNamePattern>${LOG_HOME}/jobs/${jobName}.%d{yyyy-MM-dd}.gz</fileNamePattern>
                    <maxHistory>30</maxHistory><!--保存最近30天的日志-->
                </rollingPolicy>
                <encoder charset="UTF-8">
                    <pattern>${LOG_PATTERN}</pattern>
                </encoder>
            </appender>
        </sift>
    </appender>

sift里包的就是代理的appender，俗称工具人，他们会各自执行自己分配到的日志事件。那他们怎么明确自己分配到什么事呢？我们直接使用默认的discriminator即MDCBasedDiscriminator，我们在业务job里进行设置MDC的key-value，如下

    public void execute(final ShardingContext shardingContext) {
    //这里
        MDC.put("jobName","firstJob");
        log.info("====First Job Begin====");
        log.info(String.format("Item: %s | Time: %s | Thread: %s | %s", shardingContext.getShardingItem(), LocalDateTime.now(), Thread.currentThread().getId(), "FIRST JOB"));
        List<Foo> data = fooRepository.findTodoData(shardingContext.getShardingParameter(), 10);
        for (Foo each : data) {
            fooRepository.setCompleted(each.getId());
        }

        log.debug("test debug");

        log.error("test error");

        log.info("====First Job End====");
        //执行完任务，移除key
        MDC.remove("jobName");
    }

上面的这里我创建了一个logger，和root logger区别开来，因为我只希望job相关的业务才这么做。但是为了主日志，错误日志也能够正常打印出来，ad­di­tiv­ity 属性我没有设置成false。

    <logger name="com.push.job" level="info" >
        <appender-ref ref="SIFT"/>
    </logger>

至此我们的配置需求都能够全部满足了，我们看一下成品配置文件（控制台打印的我也一起放在同一个配置文件里）

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">

    <!--日志文件所在目录-->
    <property name="LOG_HOME" value="backup"/>

    <property name="LOG_JOB_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread]  [%X{jobName}] %logger{0} %msg%n"/>

    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread]  %logger{0} %msg%n"/>

    <!--控制台-->
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <!--解决乱码问题-->
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <!--滚动文件-->
    <appender name="infoRollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>push-info.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/push-info.%d{yyyy-MM-dd}.log</fileNamePattern>
            <!--保存最近30天的日志-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!--滚动文件-->
    <appender name="errorRollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>push-error.log</file>
        <!-- ThresholdFilter:临界值过滤器 -->
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>error</level>
        </filter>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/push-error.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory><!--保存最近30天的日志-->
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>



    <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
        <!--discriminator鉴别器，根据MDC这个key对应的value鉴别日志事件，然后委托给具体appender写日志-->
        <discriminator>
            <key>jobName</key>
            <defaultValue>head0</defaultValue>
        </discriminator>
        <sift>
            <appender name="File-${jobName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>jobs/${jobName}.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <fileNamePattern>${LOG_HOME}/jobs/${jobName}.%d{yyyy-MM-dd}.gz</fileNamePattern>
                    <maxHistory>30</maxHistory><!--保存最近30天的日志-->
                </rollingPolicy>
                <encoder charset="UTF-8">
                    <pattern>${LOG_JOB_PATTERN}</pattern>
                </encoder>
            </appender>
        </sift>
    </appender>

    <!--root是所有logger的祖先-->
    <root level="debug">
        <appender-ref ref="stdout"/>
        <appender-ref ref="errorRollingFile"/>
        <appender-ref ref="infoRollingFile"/>
    </root>

    <logger name="com.push.job" level="info" >
        <appender-ref ref="SIFT"/>
    </logger>


</configuration>

调优

如果你仔细看SiftingAppender源码你会发现，这个appender是继承自AppenderBase也就是同步打印日志，并非不同步，所以这个appender的性能会大大下降，为了解决这个问题，你可以自己新增一个继承于UnsynchronizedAppenderBase的ParrelSiftingAppender，这里我们就不做展开，如果感兴趣可以查看原博主的文章：一次logback多线程调优的经历

至此logback系列的学习就到这里结束了。