乐趣区

一次生产环境单机日志不打印的排查过程

背景

Q 业务系统在做发布前检查工作时,发现一台单机的主日志没有打印,而其他生产机器的日志表现则是正常的。

排查流

思考

通过 greys 观察主 service 的业务入口,发现该机器线上流量的请求接受、逻辑处理、结果反馈均正常。 排查范围就聚焦在 log jar 配置上。


解决

  1. SOF 搜索,找到一篇 log 绑定包冲突的排查 & 解决方法。排查本地是否存在绑定包冲突的问题,结果发现确实是的 ——

  1. 引入 slf4j-log4j12-empty_version.jar,排掉其他 jar 包引入的日志绑定包。
  2. 发布、部署该单机,问题解决。

原理

研究了一下 slf4j-log4j12 实现绑定的原理—— 简单来说,日志输出到单机本地,需要以下 3 类 jar 包相互配合:

  • slf4j。业务程序调用的日志接口,只有接口定义,没有实现,从而保证了代码层调用 Log 的统一
  • 日志组件。比如 log4j-api、log4j-core,是 log4j2 的内部实现;logback-classic、logback-core,是 logback 的内部实现;log4j,是 logj4 的内部实现。它们本身是没有冲突的,可以并存
  • 绑定包。将 slf4j-api 的接口绑定到对应的 log 实现上,比如 slf4j-log4j12、log4j-slf4j-impl(关键)

具体到代码实现上,就是通过 StaticLoggerBinder.getSingleton () 方法返回的单例,实现包的绑定 ——

qjt 程序中,同时存在着两类绑定包:log4j-slf4j-impl-2.7.jar 和 slf4j-log4j12-1.7.2.jar。这实际是一种意义上的日志绑定包冲突 —— 选定哪个包,取决于 ClassLoader 先加载哪个,具有一定的随机性。

  • 其他生产机 StaticLoggerBinder 的加载情况 —— 可以看到使用的是 log4j-slf4j-impl-2.7.jar

  • 问题单机 StaticLoggerBinder 的加载情况 —— 可以看到使用的是 slf4j-log4j12-1.7.2.jar

核心:slf4j-log4j12 意指 slf4j 底层桥接到 log4j;log4j-slf4j-impl 意指 log4j 底层桥接到 slf4j。通过机器本地 lib 库也可以看到,qjt 用的 facade 是 log4j。所以如果 classloader 先加载了 slf4j-log4j12 的话,就会无法打印日志 —— 因为 log4j 找不到具体的桥接实现了。

再来看一下 slf4j-log4j12-empty_version.jar 是什么东东。通过观察它的包结构,可以看到其实是 slf4j 绑定包的空实现,由此排掉了其他 jar 包引入的 slf4j-log4j12 实现。

小结

叙述到此,可以发现正是 ClassLoader 随机加载两类绑定包的不同,从而导致了日志打印表现的不同。为了避免该情况,强烈建议各位同学排查是否存在绑定包的冲突。

退出移动版