一、事件背景：
某天凌晨，一阵急促的铃声将我从周公那里拉了过来，接听电话后，一脸懵逼。
什么情况？XX后台宕机了？当日日志也不打印了，前端发起的请求，都报超时，重启后又恢复了，不清楚会不会再次宕机。
出现这种情况，我第一时间想的是为什么是00:00:00宕机？难道后台嫌我这个大龄程序员睡得早了？
然后是通过远程视频，看日志，排查了凌晨之前的日志里的所有异常，均无有效的线索，毫无头绪。
这就大半夜的见鬼了，看来一时半会搞不定，看来得心爱的野摩托出马了，匆匆赶到客户现场，然后巴拉巴拉小魔仙，各种猜测、验证。
二、项目情况说明：
根据问题现象，最明显的地方是出现了日志打印异常，怀疑日志打印那块的功能导致的宕机。
于是，我静下心来研究下该后台使用的日志架构。
先看pom.xml文件，然后找日志相关组件，
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>log4j-over-slf4j</artifactId>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
</dependency>
最后在某jar包里，发现了这个配置：logback-spring.xml
三、问题分析思路：
logback-spring.xml关键配置：
<appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文件的路径及文件名 -->
<file>${log.path}/dev.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- 日志归档 -->
<fileNamePattern>${log.path}/dev/dev-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>1000MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文件保留天数-->
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
从问题现象来看，凌晨以后，../dev/dev-2023-04-13.0.log能够正常生成，而dev.log不行。
说明宕机可能出现的地方在这个环节之间。那就先分析代码吧。
四、宕机原因分析：
看上述配置文件中，有个比较关键的日志策略类：TimeBasedRollingPolicy，没说的，先找api文档吧。具体见下。
https://logback.qos.ch/apidocs/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.html
其中有一行比较关键：
void rollover() 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.java public 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标签：log,宕机,包未,jar,dev,日志,elapsedPeriodsFileName From： https://www.cnblogs.com/y-h-c/p/17314156.html