详解Spring Boot下使用logback 记录多个文件日志

Z时代
2024-01-10
分类：综合

背景

这两天遇到一个比较有意思的日志问题.

近期对我之前的python代码进行java的重构, 一方面是因为java使用的医疗库非常健全稳定, 可以商用. 另一方面是因为java速度快, 这个库的实现的效率也高, 性能是Python版本的好几倍.

但是作为这个项目的唯一作者, 我的癖好也成为这个项目的风格. 这个项目会给很多部署工程师使用. 当然项目的可用性和性能作为第一考虑的因素, 但是作为一个懒人, 对使用软件时候的复杂部署过程和混乱调试信息深恶痛绝. 所以我在项目中使用了高度可配置/易用和多文件日志.

说道多文件日志, 它的优点是每个日志只容纳自身的逻辑, 所以对于一般的入门开发者或者是初级运维工程师查看起来非常方便.

初步尝试

因为spring boot的配置一般来讲是application.properties, 但是同时开发者可以使用yml格式的配置, 二者相比, yml文件更为简洁. 熟读python之禅的我当然是简洁胜于冗余选择了yml.

发现spring-boot可以通过application.yml配置日志. 高兴的配置一番之后发现没法配置多个logger, 弃用! 改用logback-spring.xml(为什么不用logback.xml? 因为-spring这种文件可以获取到spring配置中的变量.下面再说)

第一次实现

我有好几个服务需要打日志. 一般来讲我的日志风格是 *.log 保存 INFO以上级别日志. *.err.log保存ERROR以上级别日志. 我如果每个文件日志都使用一个Appender的话, 配置文件太长了. 而且很难看, 不是我的风格.

Google了一下, 发现了这种方案:


<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  # 下面这一行的意思是使用application.yml中的global.log-dir变量
  <springProperty scope="context" name="LOG_DIR" source="global.log-dir" defaultValue="./log/"/>
  <!-- 追加器开始 -->
  # 这个是一个可以定义变量的Appender
  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    # 使用 LoggerNameBasedDiscriminator 这个类根据当前Logger获取变量
    <discriminator class="com.utils.loggers.LoggerNameBasedDiscriminator">
      <defaultValue>general</defaultValue>
    </discriminator>
    <sift>
      # 根据变量loggerName名字生成根据日期滚动的Appender
      <appender name="FILE-${loggerName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>
          ${LOG_DIR}/${loggerName}.log
        </file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <fileNamePattern>
            ${LOG_DIR}/${loggerName}.%d{yyyy-MM-dd}.log.gz
          </fileNamePattern>
          <maxHistory>15</maxHistory>
        </rollingPolicy>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
          <level>INFO</level>
        </filter>
        <encoder>
          <pattern>%d{HH:mm:ss.SSS} %-5level - %msg%n
          </pattern>
        </encoder>
      </appender>
      <appender name="FILE-ERROR-${loggerName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/${loggerName}.err.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <fileNamePattern>
            ${LOG_DIR}/${loggerName}.%d{yyyy-MM-dd}.err.log.gz
          </fileNamePattern>
          <maxHistory>15</maxHistory>
        </rollingPolicy>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
          <level>ERROR</level>
        </filter>
        <encoder>
          <pattern>%d{HH:mm:ss.SSS} %-5level - %msg%n
          </pattern>
        </encoder>
      </appender>
    </sift>
  </appender>
  <!-- 追加器结束 -->
  <!-- 日志开始 -->
  <logger name="com.some.service" level="INFO" additivity="false">
    <appender-ref ref="SIFT"/>
  </logger>
  <!-- 日志结束 -->
</configuration>

下的是对应的 LoggerNameBasedDiscriminator 类


package com.utils.loggers;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.sift.AbstractDiscriminator;
public class LoggerNameBasedDiscriminator extends AbstractDiscriminator<ILoggingEvent> {
  private static final String KEY = "loggerName";
  private String defaultValue;
  public String getDefaultValue() {
    return defaultValue;
  }
  public void setDefaultValue(String defaultValue) {
    this.defaultValue = defaultValue;
  }
  # 这就是之所以xml里面可以引用loggerName变量的原因
  public String getKey() {
    return KEY;
  }
  public void setKey() {
    throw new UnsupportedOperationException("Key not settable. Using " + KEY);
  }
  public String getDiscriminatingValue(ILoggingEvent e) {
    String loggerName = e.getLoggerName();
    if (loggerName == null)
      return defaultValue;
    else {
      String[] split = loggerName.split("\\.");
      return split[split.length - 1];
    }
  }
}

最开始我的日志里面没有报错信息, 正常的生成INFO日志. 但是后来发现事情好像不是想象的那样

问题出现

后来我把程序改成多线程. 发现所有涉及到多线程的服务日志里面都没信息了. Google半天, 发现几个令我震惊的真相:

真相1: 所有滚动Appender都不支持异步追加 (其实也不是, 但是那种方式需要写死日志文件名, 不推荐, 不讲)

真相2: SiftingAppender 内部最多嵌套一个Appender. 所以理论上我的ERROR的日志里面应该永远不会有内容.

问题解决

对于之前的两个问题, 分而治之.

不支持异步

再次谷歌(到这里读者基本上发现了我搬砖的本质), 发现有个Appender名字叫AsyncAppender, 这玩意是一个其他Appender的Wrapper. 说白了, 就是你打日志的命令是异步的, 放到队列里面, 而它真正的打日志的动作是一个单独的同步线程. 这就牛逼了, 使用这玩意收集我所有日志, 然后再转发给SiftingAppender 进行分发即可.

SiftingAppender 内部最多嵌套一个Appender

这个好办, 把INFO的Appender和ERROR的Appender拆开放到两个SiftingAppender里面就行了, 不过这样的话, 前面提到的的AsyncAppender 也要写两个.

最后, logback-spring.xml文件如下


<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <springProperty scope="context" name="LOG_DIR" source="global.log-dir" defaultValue="./log/"/>
  <!-- 追加器开始 -->
  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="com.utils.loggers.LoggerNameBasedDiscriminator">
    </discriminator>
    <sift>
      <appender name="FILE-${loggerName}"
           class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/${loggerName}.log</file>
        <rollingPolicy
            class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <fileNamePattern>
            ${LOG_DIR}/${loggerName}.%d{yyyy-MM-dd}.log
          </fileNamePattern>
          <maxHistory>15</maxHistory>
        </rollingPolicy>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
          <level>INFO</level>
        </filter>
        <encoder>
          <pattern>%d{HH:mm:ss.SSS} %-5level - %msg%n
          </pattern>
        </encoder>
      </appender>
    </sift>
  </appender>
  <appender name="SIFT-ERR" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator class="com.infervision.utils.loggers.LoggerNameBasedDiscriminator">
    </discriminator>
    <sift>
      <appender name="FILE-ERROR-${loggerName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/${loggerName}.err.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <fileNamePattern>
            ${LOG_DIR}/${loggerName}.%d{yyyy-MM-dd}.err.log
          </fileNamePattern>
          <maxHistory>15</maxHistory>
          <totalSizeCap>50MB</totalSizeCap>
        </rollingPolicy>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
          <level>ERROR</level>
        </filter>
        <encoder>
          <pattern>%d{HH:mm:ss.SSS} %-5level - %msg%n
          </pattern>
        </encoder>
      </appender>
    </sift>
  </appender>
  <!-- 异步输出 -->
  <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender">
    <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
    <discardingThreshold >0</discardingThreshold>
    <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
    <queueSize>512</queueSize>
    <!-- 添加附加的appender,最多只能添加一个 -->
    <appender-ref ref ="SIFT"/>
  </appender>
  <!-- 异步输出 -->
  <appender name ="ASYNC-ERR" class= "ch.qos.logback.classic.AsyncAppender">
    <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
    <discardingThreshold >0</discardingThreshold>
    <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
    <queueSize>512</queueSize>
    <!-- 添加附加的appender,最多只能添加一个 -->
    <appender-ref ref ="SIFT-ERR"/>
  </appender>
  <!-- 追加器结束 -->
  <!-- 日志开始 -->
  <logger name="com.some.service" level="INFO" additivity="false">
    <appender-ref ref="ASYNC"/>
  </logger>
  <!-- 日志结束 -->
</configuration>