日志方法执行了,不代表日志已经输出

商品导入代码调用 logger.info,运行没有抛异常,控制台却只有“没有找到 provider”的诊断。另一个应用引入两套日志依赖后开始输出,但实际选择的实现与预期不同。这两种现象都发生在业务日志格式化之前,首先需要检查门面如何找到实现。

SLF4J API 提供调用接口,provider 负责连接到具体日志系统。把 API 放入依赖树只证明能够编译日志调用,不能证明运行时有可用输出实现。相反,公共类库如果强制带入一个 provider,可能与宿主应用自己的选择发生冲突。

本篇固定 SLF4J API、simple、jdk14 与 jul-to-slf4j 为 2.0.20。Java 8 基线,在 Zulu 8.0.472 和 Corretto 21.0.11 运行。完整探针每个场景启动独立 JVM,并保存 classpath、stdout 和 stderr;运行说明包含复跑方式。日志内容边界可参照 第 22 篇。

Provider 发现是运行时协议

LoggerFactory 固定源码先尝试显式指定的 provider,否则通过加载 LoggerFactory 的类加载器执行 ServiceLoader 查找。初始化阶段检查数量,再使用发现列表中的一个 provider 初始化工厂;没有找到时进入 NOP 回退。

本实验没有设置显式 provider 属性,也没有自定义类加载器。探针先用 ServiceLoader 枚举实际发现项,再调用 LoggerFactory 取得最终工厂类型。这样能分别观察“可发现多少个实现”和“最终初始化了哪个工厂”,而不是根据 Maven 依赖声明猜测结果。

无 provider 场景的 classpath 只包含测试类目录与 slf4j-api。探针发现数量为零,工厂为 NOPLoggerFactory,stderr 含没有找到 provider 的诊断。业务 info 调用未抛异常,也没有输出对应记录。这个结果解释了为什么“代码成功走到日志语句”不足以证明日志可见。

单 simple provider 场景发现数量为一,最终工厂为 SimpleLoggerFactory,stderr 包含受控商品信息。两个 provider 场景发现数量为二,stderr 出现 multiple providers 诊断。测试只要求数量和诊断符合预期,不把某一个胜出者写成不变结论。

官方错误说明要求应用明确选择一个 provider。源码中使用列表首项,不代表应用可以依赖某种稳定的依赖顺序来选择实现;打包、类加载器与运行方式改变后,发现次序可能变化。解决方式是消除歧义,或使用明确配置,而不是观察一次输出后认定顺序永久固定。

为什么必须分进程验证

LoggerFactory 的初始化状态在进程内保留。先用一个 classpath 完成初始化,再试图删除或替换 provider,无法等价模拟全新应用启动。测试如果只在同一个 JVM 中连续改变变量,可能检查的是早先初始化的工厂,而不是当前希望验证的配置。

本章 fork 命令只选择需要的 jar。无 provider、simple、jdk14、多 provider、桥接分别使用独立进程,最多等待二十秒,超时则结束子进程。每个进程把真实诊断输出写入独立文件,避免把 JUnit 进程自身的日志输出误认成目标场景。

实验工程为构造多种 classpath,同时声明了两个测试 provider,所以总测试进程可能出现多 provider 诊断。这是实验夹具配置,不是推荐的应用部署配置。需要分析 provider 选择时,应读取对应 fork 的证据,不能拿主测试进程的工厂替代。

第一条可迁移模式是隔离全局初始化。日志工厂、系统属性驱动的单例、字符集启动参数以及服务发现机制,都可能只在特定阶段读取配置。验证不同启动条件时,独立进程往往比重置几个字段更接近真实入口。

参数占位符不会阻止 Java 求值

探针把 debug 级别关闭,再调用 logger.debug(“eager {}”, calls.incrementAndGet())。随后使用 fluent API 的 addArgument supplier 提交同样的递增操作。最终计数为一:普通参数在进入日志方法之前已经求值,supplier 在禁用级别下没有执行。

占位符可以避免某些不必要的字符串格式化,但不能撤销 Java 已经完成的参数计算。把昂贵查询、完整 JSON 序列化或副作用函数放进普通参数,即使日志最终不输出,也可能执行这些操作。业务行为更不应该依赖某条日志是否启用。

固定 NOPLoggingEventBuilder的 supplier 重载直接返回空操作 builder,没有调用 supplier.get。配合 Logger 的禁用级别路径,可以解释实验中的计数差异。

这不意味着任何接收 lambda 的日志调用都自动便宜。创建 lambda 捕获的对象可能已在之前构造;supplier 内部如果读取不断变化的状态,启用时取得的值也可能与调用前不同。需要表达稳定快照时,应明确采样时间,不能仅为延迟计算而改变诊断含义。

本章只比较调用次数,没有测量纳秒耗时、分配量或不同 provider 的格式化性能。计数直接回答“是否执行”,但不能回答“快了多少”。性能结论需要等价负载、预热和实际输出策略的单独实验。

MDC 清理属于请求生命周期

MDC 的实现由 provider 提供。官方 MDC 文档说明 simple 使用空操作适配器,jdk14 使用 BasicMDCAdapter。因此本章把 MDC 断言放在只有 jdk14 的 fork 中,避免在空操作适配器上得到“没有泄漏”的假证据。

探针先设置 requestId=req-A,确认立即读取到该值,然后模拟请求失败,在 finally 删除该键。后续读取为 null。这里同时验证了“确实写入过”和“失败后确实移除”,而不是只检查初始空状态。

线程池中的线程会被后续请求复用。若异常路径遗漏清理,下一请求可能读取到前一请求的关联标识。相反,简单调用 clear 也可能删掉外层调用已设置的其他上下文。边界拥有哪个键,就应清理或恢复自己负责的状态,并明确嵌套调用约定。

本例从空上下文开始,finally remove 足够;若同一键原本已有值,应该先保存旧值,并在退出时恢复。MDC.putCloseable 的关闭行为是删除键,不是自动恢复任意旧上下文,使用前同样需要检查嵌套语义。

异步任务又跨越了一层边界。上下文是否继承、复制或传播,取决于适配器和任务提交方式,不能从同线程写读成功推导到线程池。需要异步关联时,应在提交和执行边界显式传递所需上下文,并在执行线程 finally 恢复或清理。本章未运行跨线程传播,不把它列为已验证能力。

第二条可迁移模式是让诊断上下文与作用域成对出现。进入时设置,成功或失败退出时恢复,作用域之外再检查一次。事务标签、追踪标识和临时线程状态都可以采用相同验收结构。

桥接方向不能组成循环

旧组件可能使用 java.util.logging。jul-to-slf4j 提供 JUL handler,把 JUL 记录转到 SLF4J;slf4j-jdk14 则把 SLF4J 调用转到 JUL。两者方向相反,名称都出现 logging 并不意味着应一起加入运行配置。

本章增加单向桥接 fork,classpath 为 API、simple 与 jul-to-slf4j。安装桥接前移除 JUL 根 logger 原有 handler,再安装 SLF4JBridgeHandler,发出一条 JUL 消息并检查 simple 的 stderr 输出;结束时卸载桥接。这个场景验证旧 API 的记录进入预定 provider,没有通过 mock logger 替代真实路由。

官方桥接说明明确指出,安装 JUL→SLF4J 桥接同时使用 SLF4J→JUL provider,会形成循环。本章没有执行这种循环配置,也没有通过无限递归来验证文档。桥接依赖图应先确定唯一输出方向,再通过小消息检查实际落点。

移除原 handler 是为了避免同一 JUL 记录同时走旧控制台和新桥接路径。实际应用可能已有其他必要 handler,不能照搬测试中的全量移除而不检查日志拓扑;应按应用的迁移边界调整,并验证是否出现重复记录或遗漏输出。

桥接改变的是调用路径,不保证保留旧系统全部配置能力。级别、格式、过滤和上下文字段需要逐项确认;具体 API 特有功能也未必能完整映射。迁移验收应包含“输出一次、输出到哪里、包含哪些字段”,而不是只验证没有类加载异常。

敏感值检查必须发生在最终输出

simple 场景输出商品标识 A 和固定占位 [REDACTED],测试检查输出含预期文本且不含合成秘密。示例的策略是在进入日志调用前选择允许输出的字段,不把完整凭据对象交给 provider,再寄希望于格式化阶段猜测哪些字段敏感。

这种检查仍有边界:本章没有把真实秘密传入日志,也没有证明任何 provider 都具备自动脱敏能力。测试只能证明示例选择的输出内容符合约定。新增字段、异常消息和嵌套对象的 toString,都可能重新扩大输出范围,应分别检查。

错误堆栈也属于日志内容。如果解析失败的异常消息包含原始请求片段,即使业务消息只输出商品编号,完整异常仍可能带出其他字段。日志验收可以使用合成敏感值贯穿请求与异常路径,检查最终输出,而不需要使用真实用户数据。

依赖树之外还要检查实际打包结果

构建文件声明了正确 provider,不等于部署包一定包含它。打包插件可能删除服务描述文件,也可能将另一套 provider 从传递依赖带入。问题定位应从实际启动 classpath、可发现服务与最终工厂逐层检查,避免仅凭依赖树截图结束排查。

本章保存每个 fork 的完整命令,正是为了让零个、一个与两个 provider 的条件可复核。若将实验改成可执行大包,还应对该产物启动同样的探针,验证服务元数据是否正确合并。这里没有制作大包,不能把普通 classpath 的通过结果外推到所有打包方式。

日志部署变更也应检查业务记录和框架诊断两个通道。前者反映实际日志落点,后者可能在初始化期间直接写 stderr;只收集应用日志文件,可能漏掉 provider 配置告警。

实验与改动题

Chapter33Test 在两个 JDK 各通过五个测试方法,隔离场景分别保存到 evidence/33 的 jdk8-forks 与 jdk21-forks。文件中包含实际命令、发现数量、工厂类型、参数计数与 stderr;没有将某次 provider 选择当成跨平台保证,也没有推导日志吞吐结论。

反例题:debug 已关闭,logger.debug(“payload {}”, serialize(request)) 是否保证 serialize 不运行?不保证。它是普通方法实参,先求值再调用日志方法。改用 supplier 才能把这项计算交给具有延迟求值契约的路径,但仍需避免副作用。

改动练习:模拟进入作用域前已有 requestId=outer,内部设置 inner 后抛异常。修改清理逻辑并断言退出后恢复 outer,再用第二次请求证明没有残留 inner。随后将该动作放入线程池任务,显式设计上下文传递,不能直接依赖同线程实验结果。

需求信号 判断模式 验收观察
没有日志 分开 API 与 provider 发现数量、工厂、stderr
多套依赖 消除启动歧义 独立进程实际 classpath
禁用级别成本 分开实参求值与格式化 计数器与 supplier
请求关联 上下文作用域闭合 设置成功、失败清理、下次读取
旧日志迁移 路由单向且无重复 桥接输出落点与次数