跳至主要內容

SLF4J、Logback 与结构化日志

高谷深陵大约 13 分钟约 4044 字
SLF4J、Logback 与结构化日志
SLF4J、Logback 与结构化日志高清原图

一条应用日志包含两类信息：message 方便人读，字段方便程序筛选。下面是一条日志的字段投影：

{
  "level": "INFO",
  "mdc": {"request_id": "request-demo"},
  "kvpList": [
    {"event": "payment.authorized"},
    {"outcome": "declined"},
    {"payment_ref": "payment-demo"}
  ]
}

event 表示发生了哪种动作，outcome 表示动作结果，payment_ref 关联业务对象，request_id 关联这次请求。授权被业务规则拒绝可以是正常处理结果；若把它一律记录为系统 ERROR，错误告警会被正常业务流量淹没。

事件经由日志框架过滤、编码和输出，之后才由采集器送进检索系统。搜索不到事件时，需要沿这条路径找到具体缺口。

日志调用如何到达输出端

门面、实现与桥接

Java 应用通常通过 SLF4J API 写日志，由运行时 provider 完成输出。Logback Classic 是一种 provider；Log4j 2 也可以提供 SLF4J 实现。

业务代码、第三方库
├─ SLF4J API ────────────────┐
├─ java.util.logging → 桥接 ┤
└─ 其他日志 API → 桥接 ─────┤
                           ↓
                    一个 SLF4J provider
                           ↓
                    Logback LoggerContext
                           ↓
                  Logger → Appender → Encoder → 输出

应用负责选择 provider；普通业务库依赖日志 API 即可，避免把输出实现强加给宿主。SLF4J 2 使用服务提供者发现机制。依赖树里多个 provider、缺 provider，以及 API 与旧实现不兼容，都会使实际输出偏离配置预期。SLF4J 手册

桥接有方向。例如将 JUL 转入 SLF4J 后，不应再把 SLF4J 转回 JUL，否则会形成循环。迁移时先梳理第三方库使用的 API，再为它们选择单向出口，同时保留两套实现通常会增加重复日志和排障成本。

Logger 层级决定哪里启用，Appender 决定送到哪里

Logger 名称通常取类全名，以点分隔形成层级：

ROOT                    level=INFO，Appender=CONSOLE
└─ store                level=ERROR，Appender=FILE
   └─ store.payment     level=DEBUG，additivity=true

没有显式级别的 Logger 向上寻找最近的已配置级别。store.payment 有自己的 DEBUG，因此 DEBUG 调用会产生事件；它可以继续送到自身及祖先的 Appender。沿祖先转交事件时，不会再次用祖先 Logger 的 ERROR 或 ROOT 的 INFO 重新做级别判断。Appender 自己的过滤器仍可拒绝事件。Logback 架构

这解释了两种常见现象：

  • 子 Logger 设为 DEBUG 后，父 Logger 的文件里也出现 DEBUG。要限制某个输出端，给相应 Appender 配置过滤器。
  • 子 Logger 和 ROOT 都绑定同一个输出端，一条事件出现两次。检查 Appender 绑定关系；需要独立输出分支时，在子 Logger 设置 additivity="false"。

级别用于控制记录成本和处理紧急度。TRACE/DEBUG 适合短时诊断，INFO 记录有业务意义的状态变化，WARN 提示异常条件但仍有可用结果，ERROR 记录本次操作无法完成且需要维护者关注的系统失败。等级约定应结合业务结果，不按是否存在异常对象机械分级。

生成一条可以按字段查询的日志

运行固定依赖的示例

下载日志与上下文实验包，在 Linux 上解压并进入 observability-core-lab。需要 Docker CLI、unzip、jq；Ubuntu/Debian 可用 sudo apt install unzip jq，RHEL 系可用 sudo dnf install unzip jq。宿主使用有 Docker 权限的普通账号；Docker 权限能控制 daemon，不能视为受限系统权限。

工程固定 SLF4J 2.0.18、Logback 1.5.38，源码目标 Java 17。下面使用 Maven 3.9.12 / Temurin 25 构建；将 Maven 镜像末尾的 25 改为 17 可复测 Java 17。构建容器显式沿用宿主 UID/GID，代码目录和缓存目录须可写。

mkdir -p .m2
docker run --rm --user "$(id -u):$(id -g)" \
  --entrypoint mvn -e HOME=/tmp -e MAVEN_CONFIG=/tmp/.m2 \
  -v "$PWD:/work" -v "$PWD/.m2:/m2" -w /work \
  maven:3.9.12-eclipse-temurin-25 -B -ntp \
  -Dmaven.repo.local=/m2 -Duser.home=/tmp \
  clean verify dependency:copy-dependencies -DincludeScope=runtime

正常结果为 8 个测试、零失败，并生成 target/classes 与 target/dependency。依赖下载失败先检查企业 Maven 仓库和网络；出现 Permission denied 则检查挂载目录所属用户，不要改成 root 来掩盖身份配置。内网环境可预先下载同版本依赖和可信镜像，经私有仓库或 docker save/load 转入，再让 Maven 使用 -o 离线运行。

示例只创建一条授权结果日志，不连接支付系统。业务代码通过字段白名单输出，没有把整个请求对象序列化：

LOG.atInfo()
   .addKeyValue("event", "payment.authorized")
   .addKeyValue("outcome", outcome)
   .addKeyValue("payment_ref", "payment-demo")
   .log("authorization completed");

addKeyValue 将键值放进事件，由具体 Encoder 决定输出格式。log() 才结束 fluent 调用并发出事件。参数化 log.info("payment={}", id) 可以延迟字符串格式化，但 log.debug("payload={}", expensiveSerialize()) 中的方法仍先执行；昂贵计算可放入受级别保护的代码或 fluent Supplier。Fluent API

JSON 编码与字段查询

示例在 src/main/resources/logback.xml 中配置：

<configuration>
  <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.JsonEncoder"/>
  </appender>
  <root level="INFO"><appender-ref ref="JSON"/></root>
</configuration>

JsonEncoder 按 JSON Lines 输出，一条事件占一个物理行，消息中的换行和引号会被转义。Logback 1.5.38 默认保留原始消息模板及参数，formattedMessage 默认关闭；需要展开后的可读消息时，显式配置 <withFormattedMessage>true</withFormattedMessage>。查询字段以实际 JSON 和 Encoder 文档为准。

运行后保存实际输出，再选择需要的字段：

docker run --rm --network none --read-only --user "$(id -u):$(id -g)" \
  -v "$PWD:/work:ro" -w /work eclipse-temurin:25.0.4_7-jdk \
  java -cp 'target/classes:target/dependency/*' \
  dev.example.observability.LoggingDemo declined > event.jsonl
jq '{level, mdc, kvpList}' event.jsonl
jq -e 'select(any(.kvpList[]; .outcome == "declined"))' event.jsonl

第一个查询得到页首投影；第二个查询应选中该事件，退出码为 0。将筛选值 declined 改成不存在的值后，jq -e 没有匹配结果会非零退出。JSON 解析失败应先看文件是否混入启动提示、纯文本堆栈或多行异常，再检查 Encoder 配置。

生产日志还需要事件时间、服务名、实例、版本、线程和异常信息；它们帮助跨进程检索和识别版本回归。上面的投影省略这些字段，实际 event.jsonl 保留框架输出。不同 Encoder 的 Schema 各不相同，不能把 Logback 的 kvpList 查询直接复制到 ECS 或另一套 Logstash 输出上。

Spring Boot 接入与异常记录

Spring Boot 4.1.1 使用默认日志配置时，可以选择结构化控制台格式：

spring.application.name=payment-service
logging.structured.format.console=logstash
logging.level.root=INFO
logging.level.com.example.payment=DEBUG

Boot 的结构化输出会整合 MDC 和 SLF4J fluent 键值。使用自定义 logback-spring.xml 后，需让 Appender 采用 Boot 对应的 StructuredLogEncoder；已有 Pattern Encoder 不会仅因上述属性就变为 JSON。配置加载、结构化格式及自定义成员选项见 Spring Boot 日志文档。

异常对象应作为异常传递：

log.atError().addKeyValue("event", "payment.provider_failed")
   .addKeyValue("error_code", "PROVIDER_TIMEOUT")
   .setCause(exception).log("provider request failed");

只记录 exception.getMessage() 会丢失类型、调用栈和 cause；层层 catch 后重复记录完整堆栈，又会让一次失败变成多条告警。通常由拥有恢复或协议翻译职责的那一层记录完整失败，中间层保留 cause 后继续传播。清理失败通过 suppressed 附加，不能覆盖最初异常。

异常消息也可能包含 SQL 参数、令牌和远端响应。敏感字段应在事件进入异步队列前移除或转换；JSON 转义解决结构破坏，不负责脱敏。请求头、Cookie、请求体和连接串不宜默认整包记录。OWASP 日志建议

异步队列怎样影响丢失与延迟

从生产线程交给工作线程

同步 Appender 在调用线程中执行，输出端变慢可以直接延长请求时间。AsyncAppender 在前面增加有界队列，由工作线程调用子 Appender；业务线程得到较短的排队时间，但队列满时仍必须在等待与丢弃之间选择。

调用线程 → 级别/过滤 → 低级事件丢弃判断 → 准备延迟处理 → 有界队列
                                                        ├─ 满时等待容量
                                                        └─ 满时直接丢弃
                                                             ↓
                                             工作线程 → 子 Appender → 输出流

准备事件时会固定部分调用线程信息，包括 MDC；需要调用位置时还要提前取得 caller data，这项操作有额外成本。业务传入的可变对象也应先转换成稳定且允许记录的值，避免输出时观察到修改后的内容。

Logback 1.5.38 的 AsyncAppender 默认队列为 256，默认丢弃阈值取队列容量的五分之一。当剩余空间低于阈值时，TRACE、DEBUG、INFO 可以提前丢弃；WARN、ERROR 继续尝试入队。neverBlock 默认 false，队列满时等待；改成 true 后，即使 ERROR 也可能因队列已满而丢失。异步 Appender

用实际队列观察三条分支

实验中的 SlowSink 阻塞第一条已经被工作线程取走的日志，通过闩锁保证后续事件确实进入同一队列。容量设为 5，因此默认丢弃阈值为 1。执行：

docker run --rm --user "$(id -u):$(id -g)" \
  --entrypoint mvn -e HOME=/tmp -e MAVEN_CONFIG=/tmp/.m2 \
  -v "$PWD:/work" -v "$PWD/.m2:/m2" -w /work \
  maven:3.9.12-eclipse-temurin-25 -B -ntp \
  -Dmaven.repo.local=/m2 -Duser.home=/tmp -Dtest=LoggingTests test

关键结果：

offered=8 delivered=7 infoDropped=1 errorBlockedThenDelivered=true
neverBlock=true offered=7 delivered=6 errorDropped=true

第一行的过程是：工作线程处理 1 条，队列存入 5 条，后续 INFO 被丢弃；再提交 ERROR 时，生产线程停在实际 ArrayBlockingQueue.put。释放输出端后，ERROR 才进入队列并交给 sink，最终收到 7 条。第二个测试关闭提前丢弃，启用 neverBlock；满队列上的 ERROR 直接丢失，最终只收到 6 条。

这些数字由测试端比较提交和接收事件得到。Logback 默认 AsyncAppender 没有自动公开一套逐事件丢弃 Counter；生产系统需要另外暴露采集缺口或选用提供此类指标的组件。仅看队列长度还会漏掉工作线程已批量取走、尚未输出的事件。固定版本队列实现

参数应与可承受的结果对应

下面关闭按级别提前丢弃，并选择满队列等待：

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>1024</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>false</neverBlock>
  <maxFlushTime>2000</maxFlushTime>
  <appender-ref ref="JSON"/>
</appender>
<root level="INFO"><appender-ref ref="ASYNC"/></root>

用它替换直接绑定 JSON 的 root，同时保留两条绑定会产生重复输出。队列容量1024按峰值事件率与可容忍缓冲时间估算，还要考虑每事件内存；2000ms的等待时间纳入应用总停机预算。两个值均需按应用负载调整。

这种配置用业务等待换取更少的队列丢失。如果日志 sink 长期慢于输入，增大队列只延迟拥塞到来。诊断日志可以接受抽样或丢低级事件时，应明确选择丢失策略并观察缺口；交易审计要求与业务状态原子一致时，需要事务记录或专用持久通道。

stop() 等待异步工作线程有时间上限。maxFlushTime 到期后，调用方可以继续退出，剩余事件仍有丢失风险；强杀进程更无法执行正常收尾。输出流 flush 也未等同于文件系统持久化，主机断电后的保存语义由文件系统和同步写入策略决定。Linux fsync

从配置、输出与采集定位日志问题

没有日志或配置未生效

先区分“没有产生事件”和“事件没到当前查询端”。普通 Logback 会查找专门配置、logback-test.xml、logback.xml，并有默认配置路径；Spring Boot 提前初始化日志系统，对配置入口还有自己的约定。Logback 配置加载

在实验目录检查运行依赖：

docker run --rm --user "$(id -u):$(id -g)" \
  --entrypoint mvn -e HOME=/tmp -e MAVEN_CONFIG=/tmp/.m2 \
  -v "$PWD:/work" -v "$PWD/.m2:/m2" -w /work \
  maven:3.9.12-eclipse-temurin-25 -B -ntp \
  -Dmaven.repo.local=/m2 -Duser.home=/tmp \
  dependency:tree '-Dincludes=org.slf4j:*,ch.qos.logback:*'

应只看到预期 API、Logback Classic 和 Core。发现另一个 provider 时，定位是哪项依赖传递引入，再在该依赖处排除。不要同时删除所有日志实现。

配置文件路径不明或 Appender 未启动时，可在一次隔离启动中添加：

-Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener

把该 JVM 参数放在 java 后、-cp 前。内部 status 会显示配置文件、Appender 启停和配置错误，输出可能混入纯文本，所以这次诊断日志不要直接送入要求全行 JSON 的输入管道。修复路径或权限后撤掉诊断参数，再用同一业务动作复测。

容器有输出，平台却查不到

容器应用写 stdout/stderr 后，由 Docker 日志驱动处理；应用写容器内部文件不会自动进入 docker logs。文件方式还需要可写目录、轮转和采集器挂载。

对自己的应用容器执行：

CONTAINER=payment-app
docker inspect --format '{{json .HostConfig.LogConfig}}' "$CONTAINER"
docker logs --tail 100 "$CONTAINER"

先把 CONTAINER 改为实际名称。若本地可见而平台不可见，继续查采集器是否读取同一路径、JSON 解析失败、传输失败、队列积压和检索时间窗。修复后用新的请求标识发送事件，确认从本地到检索端都出现，避免把历史缓存当成恢复。

Docker 默认 json-file 驱动需要显式考虑轮转；新建实验容器时可选择 --log-driver local，或在 json-file 上设置 --log-opt max-size=10m --log-opt max-file=3。这里控制的是 Docker 保存的容器输出，和 Logback RollingFileAppender 是两套存储。修改 daemon 默认配置一般不追溯改写已创建容器，需按变更计划重建相关实例。Docker 日志驱动

文件轮转要明确谁重命名文件、谁继续持有旧文件描述符、采集器是否跟随以及保留多久。应用内轮转与外部工具同时操作同一个活动文件可能产生重复或缺口。大小阈值只限制单文件，保留个数、保留周期和磁盘总量还要分别规划。

高峰期缺日志或请求变慢

先观察输入事件率和 sink 输出速率，再看异步队列及业务线程栈。业务线程停在日志队列的 put，说明输出压力已经传播到请求；队列不满但 INFO 缺失，则继续核对级别、过滤和提前丢弃阈值。应用日志完整而平台存在缺口时，压力在后面的采集或存储环节。

缩减没有诊断用途的高频事件、裁剪大字段、降低临时 DEBUG 范围，通常比先增大缓冲更直接。恢复后同时比较业务延迟、日志到达量和采集积压；只看到响应变快，可能是日志被更多地丢弃。

格式迁移时，先让新字段进入一小部分实例，核对解析成功率与关键事件查询；查询和告警切换后再删除旧格式。保留期内的旧日志仍需旧 Schema 的读取方式。实验无需常驻服务，生成物仅位于下载目录内的 target、.m2 和 event.jsonl。

权威资料与规范地址

日志 API、过滤规则、JSON 字段、队列参数和存储行为可在下列入口查阅。

跳到正文