一、Java 与 Spring 日志框架回顾
1、Java 日志框架
Java 生态有很多日志框架,构建核心就是围绕三个概念:门面、实现与桥接。比如目前较为流行的作为门面(Logging API)的 slf4j,作为实现(Logging Implementation)的 jul、logback、log4j2 等。
sfl4j 2.0.0 开始通过 ServiceLoader 机制来发现日志实现框架,它提供了 SLF4JServiceProvider 接口。logback-classic 的 LogbackServiceProvider 或者 log4j-slf4j-impl 的 SLF4JServiceProvider 就会去实现它,如果 slf4j-api 没有发现实现类,就会按照 NOP_FallbackServiceProvider 执行。
logback-classic 和 log4j-slf4j-impl 就是用于桥接 slf4j 的(Logging Bridge),将日志门面 API (slf4j-api)转换为实现(log4j-core)。以 slf4j 和 log4j2 组合为例,实现效果如下:
可以看出,日志门面的作用为多样的日志实现提供了同样的外观对象用于操作日志,在运行时加载日志实现,保持着对日志实现的扩展性。
2、Spring 日志整合
Spring 从 5.0 开始在 spring-jcl 中自带实现了 Commons Logging 桥接模块,不同于 Apache Commons Logging,它只用于统一基础框架和第三方中间件日志桥接。如果记录应用程序日志,推荐使用 slf4j+log4j2/logback 实现日志记录,这也是 Spring Boot 的自动装配设计。
以 SpringBoot 3.4.0 为例,spring-boot-starter-logging 预先按照顺序加载了 logback-classic、log4j-to-slf4j、jul-to-slf4j 三个依赖。通过指定 org.springframework.boot.logging.LoggingSystem 可以修改日志实现,对应的日志配置文件也遵照实现约定命名并提供了默认日志配置,比如 logback-spring.xml、log4j2-spring.xml。
Spring Boot 提供了 TRACE、DEBUG、INFO、WARN、ERROR、FATAL、OFF 七种日志级别,默认使用 INFO 日志级别输出到控制台。配置文件可以实现 package 粒度的日志级别控制,比如:
logging.level.root=warn
logging.level.org.springframework.web=debug
logging.level.org.hibernate=error
Spring 还支持将结构化日志输出到 Logstash、Elastic、Graylog 等组件中,实现机器可读的日志统计分析。
二、Log4j 日志写 Kakfa
这里实现一个小功能,通过日志配置文件切换日志输出到 Kafka。考虑到 Kafka 已经官方维护了一个 KafkaLog4jAppender,稳定性和扩展性都有保证,就不再扩展实现一个 Appender 了,不需要侵入代码完成日志输出切换。
1、依赖添加:Log4j2 Starter + KafkaLog4jAppender
- 从 web starter 中去除 log4j-to-slf4j 和 logback-classic 依赖,前者不能与 log4j-slf4j-impl 桥接模块共存,后者会导致多个 slf4j 实现(Class path contains multiple SLF4J providers),简洁的可以直接去除 spring-boot-starter-logging
- 添加 log4j2 starter 和 kafka-log4j-appender 依赖,用于日志写入 kafka
- 如果没有 kafka client,需要添加该依赖,KafkaLog4jAppender 会持有生产者实例发送日志消息
- lombok 不是必须的,如果使用 @Slf4j 添加该依赖
完整的依赖关系如下:
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
<exclusions>
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
<dependency>
<groupId>org.apache.kafka</groupId>
<artifactId>kafka-log4j-appender</artifactId>
<exclusions>
<exclusion>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>org.apache.kafka</groupId>
<artifactId>kafka-clients</artifactId>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
</dependency>
如果是使用 SpringBoot 1.x 版本需要额外添加 kafka-log4j-appender 和 kafka-clients 版本号,spring-boot-starter-parent 是没带这两个依赖的,比如使用 1.1.1 的版本。
2、日志配置:log4j2.xml
- 配置 Kafka 接收日志地址
- 配置 Kafka Appender,日志量较大推荐使用异步发送避免日志写入线程阻塞
- 配置 Logger,注意不能使用 DEBUG 级别以免 Kafka 日志循环写入(Make sure to not let
org.apache.kafka
log to a Kafka appender onDEBUG
level, since that will cause recursive logging)
<?xml version="1.0" encoding="utf-8"?>
<Configuration status="WARN">
<properties>
<property name="log.pattern">xxx</property>
<property name="kafka.server">xxx:9092</property>
<property name="kafka.log.topic">xxx</property>
</properties>
<Appenders>
<Kafka name="kafkaLog" topic="${kafka.log.topic}" syncSend="false" ignoreExceptions="true">
<PatternLayout pattern="${log.pattern}"/>
<Property name="bootstrap.servers">${kafka.server}</Property>
<Property name="request.timeout.ms">10000</Property>
<Property name="delivery.timeout.ms">20000</Property>
<Property name="max.block.ms">50000</Property>
</Kafka>
</Appenders>
<Loggers>
<Root level="INFO">
<AppenderRef ref="kafkaLog"/>
</Root>
<Logger name="org.apache.kafka" level="WARN" additivity="false"/>
</Loggers>
</Configuration>
3、日志写入方法
-
使用 lombok 注解 @Slf4j
-
使用 slf4j 的 Logger
private final Logger logger = LoggerFactory.getLogger(this.getClass());
4、Kafka 配置
创建接收组件日志的 topic:
./kafka-topics.sh --zookeeper localhost:2181 --create --topic xxx --partitions 1 --replication-factor 1
Created topic xxx.
检查是否创建成功:
./kafka-topics.sh --zookeeper localhost:2181 --topic xxx --describe
Topic: xxx PartitionCount: 1 ReplicationFactor: 1 Configs:
Topic: xxx Partition: 0 Leader: 0 Replicas: 0 Isr: 0
或者:
./kafka-topics.sh --zookeeper localhost:2181 --list
xxx
控制台监听消费者:
./kafka-console-consumer.sh --bootstrap-server xxx:9092 --topic xxx --from-beginning
控制台发送消息验证消费能力:
./kafka-console-producer.sh --broker-list xxx:9092 --topic xxx
三、日志输出注意事项
1、Kafka 循环打印日志
上面已经提到过的不能将 Kafka 日志级别设置为 DEBUG,并且需要将 additivity 属性置为 false,否则会导致 Kafka 日志循环打印影响日志输出。Log4j 文档推荐配置:
<Logger name="org.apache.kafka" level="WARN" additivity="false"/>
2、日志打印死锁
有一个 KafkaLog4jAppender 已知死锁 bug 需要注意,应用程序初始化日志框架时使用 KafkaLog4jAppender 会实例化 Kafka Producer,锁住 send 并申请 Metadata 对象以实现消息发送,如果 Kafka Client 此时也要打印日志日志就会锁住 Metadata 对象,就会发生死锁。
"kafka-producer-network-thread | producer-1":
waiting to lock Monitor@0x00000000025fcc48 (Object@0x00000000ed680b60, a org/apache/kafka/log4jappender/KafkaLog4jAppender),
which is held by "main"
"main":
waiting to lock Monitor@0x00007fec9dbde038 (Object@0x00000000ee44de38, a org/apache/kafka/clients/Metadata),
which is held by "kafka-producer-network-thread | producer-1"
这个 bug 已经被修复,如果需要规避,可以把 Kafka 日志级别调整成 WARN,解开死锁条件,配置效果如上。
3、线程 block
高并发场景下打印日志需要注意线程 block 问题,可以参考美团技术团队总结的几项实践。