替换jar包未重启引起的系统宕机事件

一、事件背景：

某天凌晨，一阵急促的铃声将我从周公那里拉了过来，接听电话后，一脸懵逼。

什么情况？XX后台宕机了？当日日志也不打印了，前端发起的请求，都报超时，重启后又恢复了，不清楚会不会再次宕机。

出现这种情况，我第一时间想的是为什么是00:00:00宕机？难道后台嫌我这个大龄程序员睡得早了？

然后是通过远程视频，看日志，排查了凌晨之前的日志里的所有异常，均无有效的线索，毫无头绪。

这就大半夜的见鬼了，看来一时半会搞不定，看来得心爱的野摩托出马了，匆匆赶到客户现场，然后巴拉巴拉小魔仙，各种猜测、验证。

二、项目情况说明：

根据问题现象，最明显的地方是出现了日志打印异常，怀疑日志打印那块的功能导致的宕机。

于是，我静下心来研究下该后台使用的日志架构。

先看pom.xml文件，然后找日志相关组件，

  org.springframework.boot
  spring-boot-starter-logging


  org.slf4j
  log4j-over-slf4j


  org.slf4j
  jcl-over-slf4j

最后在某jar包里，发现了这个配置：logback-spring.xml

三、问题分析思路：

logback-spring.xml关键配置：

${log.path}/dev.log
TimeBasedRollingPolicy“>

${log.path}/dev/dev-%d{yyyy-MM-dd}.%i.log
SizeAndTimeBasedFNATP“>
1000MB

30

从问题现象来看，凌晨以后，../dev/dev-2023-04-13.0.log能够正常生成，而dev.log不行。

说明宕机可能出现的地方在这个环节之间。那就先分析代码吧。

四、宕机原因分析：

看上述配置文件中，有个比较关键的日志策略类：TimeBasedRollingPolicy，没说的，先找api文档吧。具体见下。

https://logback.qos.ch/apidocs/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.html

其中有一行比较关键：

voidrollover()Rolls over log files according to implementation policy.（根据实施策略滚动日志文件。）就他了，看样子是这个方法里出现异常了，反编译瞅瞅吧，试试水有多深。源码分析：public void rollover() throws RolloverFailure {

　　 //timeBasedFileNamingAndTriggeringPolicy有两个实现类：
　　 //DefaultTimeBasedFileNamingAndTriggeringPolicy.java、SizeAndTimeBasedFNATP.java。
    // 对照下logback-spring.xml中的配置，使用的是后者SizeAndTimeBasedFNATP.java，elapsedPeriodsFileName 
　  //再看这个类里这个字段的初始化，很容易猜出来，elapsedPeriodsFileName 
    //就是用来生成上一天的日志文件的，此处是：elapsedPeriodsFileName="dev-2023-04-13.0.log"

    String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();
　　//此处是去掉结尾的"/"，对文件名进行合法性处理
    String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);
　　 // compressionMode:NONE, GZ, ZIP 有此推测如下IF-ELSE用来实现文件写入，dev-2023-04-13.0.log就是在这个里面完成写入的。
    if (compressionMode == CompressionMode.NONE) {
        if (getParentsRawFileProperty() != null) {
            renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);
        } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }
    } else {
        if (getParentsRawFileProperty() == null) {
            compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);
        } else {
            compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);
        }
    }
　　 //看来问题最容易出现的地方是这里：下面应该是要生成dev.log文件，而实际没有生成
    if (archiveRemover != null) {
　　　　 //此变量的生成应该不容易引起宕机，推测是下下一步导致的宕机
        Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());
        this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);
    }
}

TimeBasedArchiveRemover.javapublic Future cleanAsynchronously(Date now) {    ArhiveRemoverRunnable runnable = new ArhiveRemoverRunnable(now);    ExecutorService executorService = context.getScheduledExecutorService();    Future future = executorService.submit(runnable);    return future;}
重点在这里：ArhiveRemoverRunnable。
这个类是内部类，用途是实现了个线程类，初看没啥问题，仔细想想，类的加载是有顺序的，有没有可能是这个内部类加载的时候，报错了？
好好的为啥加载不上了呢？谁动了他的奶酪？
各种检查、分析，发现了个奇怪的现象：
日志中打印的jar启动的时间是10点，然后jar包的最后修改时间是17点。什么鬼？难道是替换了新包没有重启，导致这个内部类加载有问题，系统宕机了？
抓紧验证一下，构造一个类似的场景：
1.修改系统时间为23:55:00.使用java -jar ***.jar启动服务。
2.准备个微调的jar包，待之前的服务启动好后，替换掉他，然后坐等零点到来。
3.激动人心的时刻到了，零点后，dev.log不见了，dev-2023-04-13.0.log有生成。抓紧看下控制台。一堆报错，最关键的信息也打印了。

　　到此，本次系统宕机的根因找到了，是jar包替换没有重启，导致日志打印那块出现中断，最后跟实时的同事要求升级包要规范，不能这样随意的操作。

五、总结：

这个问题太邪门了，尤其是凌晨暴雷，简直是要了程序员的老命，果然不管什么问题，重启试试是最有效的武器。

本次系统宕机的问题就分享到这里，谢谢大家批评指正。

timeBasedFileNamingAndTriggeringPolicy