yufan.on.software.and.others

使用 SLF4J 和 Log4j 2 为 Java 应用程序记录日志

2022-12-05, 星期一, 14:55

JavaDev

使用门面模式的日志框架，有利于维护日志处理方式的统一，项目可以根据需要自由选择 Log4j 2 或是 Logback 或是其他日志后端，而不必修改代码。

flowchart TD subgraph app [Application] end subgraph interf [日志接口] b2[slf4j] end subgraph impl [日志实现] c1[log4j2] c2[logback] ... end app --> interf --> impl

本文将介绍如何在项目中使用 SLF4J 和 Log4j 2。

private static final org.slf4j.Logger logger =
    org.slf4j.LoggerFactory.getLogger(Showcase.class);

添加 SLF4J 和 Log4j 2 支持

为了使用 Fluent Logging API 选择 SLF4J API 2.x，需要添加的 Log4j 2 依赖如下：

本文写作时 org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0 中引入的 org.slf4j:slf4j-api 版本为 2.0.0，手动添加更新的版本。

logger.atDebug()
	.addArgument(newT)
	.addArgument(oldT)
	.log("Temperature set to {}. Old temperature was {}.");

logger.atDebug()
	.addKeyValue("oldT", oldT)
	.addKeyValue("newT", newT)
	.log("Temperature changed.");

不过需注意，使用 Log4j 2 作为日志后端时，键值对会被按照 MDC 处理。

由于 SLF4J 只能绑定一个日志框架，如果 CLASSPATH 上存在多个绑定，SLF4J 将发出 SLF4J: Class path contains multiple SLF4J bindings. 警告。例如这个 Spring Boot 项目，可以看到 SLF4J 在 Logback 和 Log4j 2 之间产生了分歧。

SLF4J: Found binding in [jar:file:ch/qos/logback/logback-classic/1.2.11/logback-classic-1.2.11.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:org/apache/logging/log4j/log4j-slf4j-impl/2.17.2/log4j-slf4j-impl-2.17.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]

使用 mvn dependency:tree 分析依赖关系，发现 Spring Boot 默认使用 logback 作为日志框架，需要在 spring-boot-starter 中排除。

[INFO] |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.6.7:compile
[INFO] |  |  +- ch.qos.logback:logback-classic:jar:1.2.11:compile
[INFO] |  |  |  \- ch.qos.logback:logback-core:jar:1.2.11:compile
[INFO] |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.17.2:compile

产生日志

确定日志级别

SLF4J 和 Log4j 2 对日志级别的支持如下表所示，SLF4J 移除了 FATAL 级别。

日志级别 Log4j 2 权重 SLF4J 支持
OFF 0 -
FATAL 100 -
ERROR 200 支持
WARN 300 支持
INFO 400 支持
DEBUG 500 支持
TRACE 600 支持
ALL Integer.MAX_VALUE -

ERROR 级别一般对应不可预知，大概率需要人工干预的异常。 为方便排查问题，应当尽量多地输出方法参数、执行过程中产生的对象等数据。SLF4J 的 .error 方法支持 Throwable 类型入参，可以直接打印异常堆栈信息。

try {
    // ...
} catch (IOException ex) {
    logger.error("Invoking UserService.findUser cause error, username: {}", username, ex);
}

若异常对系统的整个流程影响不大，程序可以继续运行，则应该使用 WARN 级别。该级别主要输出警告性质的内容，这些内容是可以预知且有规划的应对方案，例如方法入参为空或者参数的值不在预期范围内。

INFO 主要为提示性质的内容，可以是生产环境的一般性信息输出，如：

  • 应用启动时所加载的配置参数值（如连接参数、线程池参数、超时时间等，以及一些与环境相关的配置，或者是整个配置参数）
  • 一些重要的依赖注入对象的类名
  • Service 方法的输入参数值、返回值，由于一些方法入参的值非常多，只在入口处输出一次就可以了，在服务方法内部或者调用非服务方法时就不需要再输出了
  • 方法中重要的部分，比如从数据库中所获取较为重要的数据，以及调用第三方接口的输入参数值和接口返回值

DEBUG 和 TRACE 级别输出调试性质的内容，该级别日志主要用于在开发、测试阶段输出。这个级别的日志应尽可能详尽，可以包括参数信息，调试细节信息，返回值信息等等，便于在开发、测试阶段出现问题或者异常时对其进行分析。

拼接日志内容

logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);

把日志的输出过滤级别设置为 ERROR，则日志不会输出，但字符串还是会被拼接。如果更耗费时间 / 浪费内存的操作不可避免，可以先判断日志过滤级别。

if (logger.isDebugEnabled()) {
    logger.debug("Temperature set to " + t + ". Old temperature was " + oldT);
}

当然这还是会导致对日志级别进行两次检查，一次在调用 isDebugEnabled 时发生，一次在调用 debug 时发生。

建议不要在日志中调用对象的方法获取值，除非你想得到一个 NullPointerException。直接打印这个对象，就算是 null 也没关系。

logger.debug("current user is {}", user);

日志在输出对象时实际上调用了类的 toString 方法，可以重写这个方法以便在日志中屏蔽敏感信息或是展示自定义信息，但注意最好不要用 JSON 工具做序列化，也不建议通过反射去做这个工作，以免日志过多地影响性能。

配置 Log4j 2

Log4j 2 支持 .properties、YAML、JSON 和 XML 格式的配置文件，加载时会先查询 log4j2.configurationFile 属性，然后在 CLASSPATH 中查找 log4j2-test.* 文件，其次是 log4j2.* 文件。都找不到就会启用默认配置通过控制台输出日志。

在 Spring Boot 项目中根据不同的 Profile 修改 log4j2.configurationFile 属性就可以加载相应的配置。

@Profile("prod")
@Component
public class ProductionEnvPropertySetter {
    @PostConstruct
    public void setProperty() {
        System.setProperty("log4j2.configurationFile", "log4j2-prod.yml");
    }
}

@Profile("local")
@Component
public class LocalEnvPropertySetter {
    @PostConstruct
    public void setProperty() {
        System.setProperty("log4j2.configurationFile", "log4j2-local.yml");
    }
}

使用 JSON 和 YAML 格式的配置需要添加一些运行时依赖。org.springframework.boot:spring-boot-starter-web 已经包含了解析 JSON 所需的 com.fasterxml.jackson.core:jackson-core 和 com.fasterxml.jackson.core:jackson-databind，YAML 则需要 com.fasterxml.jackson.dataformat:jackson-dataformat-yaml。

Appender

Appender 负责把日志事件送往目的地，通常使用 ConsoleAppender 和 FileAppender/RollingFileAppender，要把日志记录到数据库中，还可以使用 JDBCAppender。

PatternLayout 与 Pattern

使用 PatternLayout 输出日志时，日志事件会被组装为一个字符串，而 Pattern 描述了装配格式。具体的语法规则可以参考 Patterns | Log4j。

Pattern 的参数名有时会有全名和缩写两种写法，由于全名在大多数情况下都可以自解释，以下的 Pattern 示例将使用全名，推荐在实际开发中也这样做。

%date{ISO8601_OFFSET_DATE_TIME_HHMM} %-5level %logger{1.} %variablesNotEmpty{TRACE=%MDC{traceId}} %MDC: %message%n
  • %date{ISO8601_OFFSET_DATE_TIME_HHMM}：输出日志产生的日期时间，顺便声明使用 ISO8601 日期时间格式
  • %-5level：输出日志级别，占用 5 个字符宽度，左对齐用空格补零
  • %logger{1.}：通过 %class 和 %method 获取触发日志事件的类和方法是一个昂贵的操作，一般用产生日志的 Logger 名称作为替代。{1.} 表示 package 部分只取首字母，{1} 的效果则与 java.lang.Class.getSimpleName() 相同
  • %variablesNotEmpty{pattern}：当 pattern 中使用的变量都有值时输出 pattern 的结果
  • %MDC：MDC
  • %message：日志信息，一般也包含 %throwable 代表的异常堆栈
  • %n：插入一个对应平台的换行字符

使用 RollingFileAppender 实现日志分割、归档与清理

测试 / 生产环境应当把日志输出到文件中，每天产生一个文件（日志量庞大时可以每个小时产生一个日志文件）。生产环境可以考虑使用异步文件输出，不过该种方式会产生日志延时，尤其是在停止应用时可能会导致一些还在内存中的日志未能及时写入而丢失。

# 日志文件滚动更新
# 满足一定条件后（如文件达到指定大小或达到指定时间）重命名日志文件进行归档
# 同时生成新的日志文件用于写入
# 如果还设置了一定时间内允许归档的日志文件的最大数量（DefaultRolloverStrategy），将删除旧的日志文件
RollingFile:
    # name 供 logger.AppenderRef.ref 使用
  - name: RollingFile_Appender
    # 用于实时写入的日志文件
    filename: ${log-path}/app.log
    # 归档文件命名规则
    filePattern: "${log-path}/archives/${app-name}_%d{yyyy-MM-dd}.%i.log.gz"
    PatternLayout:
      # 日志格式
      pattern: "%date{ISO8601_OFFSET_DATE_TIME_HHMM} %level [${app-name}] %logger{1.} %MDC: %message%n"
    Policies:
      # 文件达到指定大小后切分
      # 由于归档文件使用 gzip 进行了压缩，单个归档文件的体积预计为阈值的十分之一
      SizeBasedTriggeringPolicy:
        size: 50MB
      # 按时间切分日志
      TimeBasedTriggeringPolicy:
        interval: 1d
    # rollover 策略，默认为 7
    # 如果 filePattern 中含有整数计数器（%i）而 datetime pattern 不存在或未达到下一个时间段
    # 每次 rollover 计数器加 1，达到 max 后从 1 重新开始，开始覆盖旧文件
    DefaultRolloverStrategy:
      max: 7
      # 还可以配置 delete 策略，删除旧的日志文件

可以编写测试程序输出大量日志信息，看看是否会触发日志分割。

接入云服务商的日志服务

几大云服务商的日志服务，如阿里云的 SLS 和腾讯云的 CLS，都提供了 Log4j 2 Appender。

以腾讯云 CLS 为例，添加 com.tencentcloudapi.cls:tencentcloud-cls-log4j2-appender 依赖，同时排除 ch.qos.logback:logback-classic 和 ch.qos.logback:logback-core。

Loghub:
  - name: Loghub_Appender
    endpoint: ${cls-endpoint}
    topicID: ${env:CLS_TOPIC_ID}
    accessKeyId: ${env:CLS_ACCESS_KEY_ID}
    accessKeySecret: ${env:CLS_ACCESS_KEY_SECRET}

在编写 Appender 配置时，使用 ${VAR_NAME} 读取配置文件中 Configuration.Properties.Property[] 定义的变量，使用 ${env:VAR_NAME} 读取环境变量。

Configuration:
  Properties:
    Property:
      - name: app-name
        value: loggingShowcase
      - name: cls-endpoint
        value: ap-guangzhou.cls.tencentcs.com

使用 Syslog 接入日志审计系统

一些日志审计系统支持从 Syslog 读取日志，可以使用 SysLog Appender 把日志写入 Syslog。

Syslog:
  - name: Syslog_Appender
    format: RFC5424
    host: localhost
    port: 514
    protocol: UDP
    immediateFail: false
    ignoreExceptions: true
    reconnectionDelayMillis: 250
    appName: ${app-name}
    facility: LOCAL0
    PatternLayout:
      # 日志格式
      pattern: "[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n"

主流 Linux 发型版大多把 RSYSLOG 作为主要的日志实现，根据 Appender 的配置，修改 /etc/rsyslog.conf 使其支持在 514 端口上监听 UDP 协议的日志输入。

# provides UDP syslog reception
module(load="imudp")
input(type="imudp" port="514")

可以在 /var/log/messages 中读取日志。

Logger

Logger 根据日志级别过滤日志，把日志送往不同的 Appender。

Loggers:
  Root:
    level: warn
    AppenderRef:
      ref: RollingFile_Appender
  logger:
    - name: cc.ddrpa.loggingshowcase
      level: warn
      # 防止满足其他 logger 条件时重复打印日志
      additivity: false
      AppenderRef:
        # 指定日志通过什么途径输出输出
        - ref: Loghub_Appender
        - ref: RollingFile_Appender

异步日志

主要的几种 Appender 和 Logger 默认情况下都是同步的。如果从程序性能的角度考虑，需要在一个合适的时间集中处理日志，可以使用他们的异步版本：Async(Appender) 和 AsyncLogger/AsyncRoot。Async(Appender) 使用 ArrayBlockingQueue 作为队列，AsyncLogger/AsyncRoot 则依赖外部队列 com.lmax:disruptor。推荐使用异步 Logger 而不是异步 Appender。

在日志中添加额外信息

调用链标识

在分布式应用中，用户的一个请求会调用若干个服务完成，这些服务可能还是嵌套调用的，因此完成一个请求的日志有可能分散在多个服务中。调用链标识可以串联起单个请求在整个系统中的调用日志。

  • 唯一字符串 traceId
  • 调用层级 spanId

业务标识

业务开发中有时需要根据用户或者业务做聚类分析，可以将聚类标识打印到日志中。

  • 用户标识 userId
  • 业务标识 bizId

信息安全

参考 日志系统的隐私安全问题。

Lombok Annotation

使用 Lombok 的项目可以在类或者枚举上添加 @Slf4j 注解，然后在代码使用 log 对象记录日志。

@Slf4j
public class LogExample {
}
// 相当于
public class LogExample {
    private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(LogExample.class);
}