今日总结 – springboot日志系统的设计缺陷

hook默认值从false改成了true,暴露了问题,进程关闭时日志系统可能先于spring容器关闭,造成无法打印日志

先了解一下springboot中关闭spring容器的机制

  • spring.main.register-shutdown-hook参数默认是true,该参数会注册jvm hook在进程关闭时关闭spring容器

再来看下springboot中关闭日志系统的机制

  • logging.register-shutdown-hook参数默认是true,该参数会注册jvm hook在进程关闭时关闭日志系统
  • 以logback为例看shutdownHook就是直接调用的stop

问题分析

  • 所以可以看出springboot的容器关闭和日志系统关闭用伪代码表示就是
Runtime.getRuntime().addShutdownHook(new Thread(() -> spring.stop));

Runtime.getRuntime().addShutdownHook(new Thread(() -> logSystem.stop));

-jvm的不同shutdownHook执行是并行的也就造成了,spring容器的关闭和日志系统关闭时间先后的不确定

  • 在springboot2.5.0之前,logging.register-shutdown-hook默认false,不会注册日志系统的shutdownHook,所以该问题不明显,只有在使用异步appender的时候才有可能出问题

jvm关闭时,异步append的打印队列中还有未打印的日志时,这些日志就丢了

  • 从工程依赖关系看:用户业务 -> spring -> 包括日志系统在内的基础组件。在这种单向依赖的设计下,spring除了要对上层的用户业务暴露出生命周期回调接口外,还应该对下层依赖的基础组件暴露出生命周期的回调接口才对,比如下图红圈里就应该提供一个回调
  • spring关闭后只是将active标示为了false,并没有回调
  • 该问题已经在社区被注意到了,但是修复起来好像比较麻烦,因为日志系统的关闭一开始从设计上的思路就不对,就不该依赖并行的jvm shutdownHook。现在springboot的修复方法很不优雅,通过弱引用+不断调用isActive来判断spring的关闭

https://github.com/spring-projects/spring-
boot/issues/26660

3种解决办法

  • 等待springboot修复
  • 使用2.5.0之前的springboot,或将logging.register-shutdown-hook设为false,并且不要使用异步appender打印日志
  • 不使用springboot提供的关闭日志系统机制,自己实现。以logback为例,自己在代码中实现ch.qos.logback.core.hook.ShutdownHookBase并在logback-spring.xml中配置

注意:实现ShutdownHookBase的类自己添加到jvm
hook中会失效,只能在配置文件中使用,logback解析配置文件时会把context传入到该类中

正文完