一、事件背景：
某天凌晨，一阵急促的铃声将我从周公那里拉了过来，接听电话后，一脸懵逼。
什么情况？XX后台宕机了？当日日志也不打印了，前端发起的请求，都报超时，重启后又恢复了，不清楚会不会再次宕机。
出现这种情况，我第一时间想的是为什么是00:00:00宕机？难道后台嫌我这个大龄程序员睡得早了？
然后是通过远程视频，看日志，排查了凌晨之前的日志里的所有异常，均无有效的线索，毫无头绪。
这就大半夜的见鬼了，看来一时半会搞不定，看来得心爱的野摩托出马了，匆匆赶到客户现场，然后巴拉巴拉小魔仙，各种猜测、验证。
二、项目情况说明：
根据问题现象，最明显的地方是出现了日志打印异常，怀疑日志打印那块的功能导致的宕机。
于是，我静下心来研究下该后台使用的日志架构。
先看pom.xml文件，然后找日志相关组件，- <dependency><br> <groupId>org.springframework.boot</groupId><br> <artifactId>spring-boot-starter-logging</artifactId><br></dependency><br><dependency><br> <groupId>org.slf4j</groupId><br> <artifactId>log4j-over-slf4j</artifactId><br></dependency><br><dependency><br> <groupId>org.slf4j</groupId><br> <artifactId>jcl-over-slf4j</artifactId><br></dependency>
三、问题分析思路：
logback-spring.xml关键配置：
${log.path}/dev.log
${log.path}/dev/dev-%d{yyyy-MM-dd}.%i.log
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
其中有一行比较关键：
void rollover() Rolls over log files according to implementation policy.（根据实施策略滚动日志文件。）就他了，看样子是这个方法里出现异常了，反编译瞅瞅吧，试试水有多深。源码分析：public void rollover() throws RolloverFailure {- //timeBasedFileNamingAndTriggeringPolicy有两个实现类：<br> //DefaultTimeBasedFileNamingAndTriggeringPolicy.java、SizeAndTimeBasedFNATP.java。<br> // 对照下logback-spring.xml中的配置，使用的是后者SizeAndTimeBasedFNATP.java，elapsedPeriodsFileName <br> //再看这个类里这个字段的初始化，很容易猜出来，elapsedPeriodsFileName <br> //就是用来生成上一天的日志文件的，此处是：elapsedPeriodsFileName="dev-2023-04-13.0.log"
- String elapsedPeriodsFileName = timeBasedFileNamingAndTriggeringPolicy.getElapsedPeriodsFileName();<br> //此处是去掉结尾的"/"，对文件名进行合法性处理<br> String elapsedPeriodStem = FileFilterUtil.afterLastSlash(elapsedPeriodsFileName);<br> // compressionMode:NONE, GZ, ZIP 有此推测如下IF-ELSE用来实现文件写入，dev-2023-04-13.0.log就是在这个里面完成写入的。<br> if (compressionMode == CompressionMode.NONE) {<br> if (getParentsRawFileProperty() != null) {<br> renameUtil.rename(getParentsRawFileProperty(), elapsedPeriodsFileName);<br> } // else { nothing to do if CompressionMode == NONE and parentsRawFileProperty == null }<br> } else {<br> if (getParentsRawFileProperty() == null) {<br> compressionFuture = compressor.asyncCompress(elapsedPeriodsFileName, elapsedPeriodsFileName, elapsedPeriodStem);<br> } else {<br> compressionFuture = renameRawAndAsyncCompress(elapsedPeriodsFileName, elapsedPeriodStem);<br> }<br> }<br> //看来问题最容易出现的地方是这里：下面应该是要生成dev.log文件，而实际没有生成<br> if (archiveRemover != null) {<br> //此变量的生成应该不容易引起宕机，推测是下下一步导致的宕机<br> Date now = new Date(timeBasedFileNamingAndTriggeringPolicy.getCurrentTime());<br> this.cleanUpFuture = archiveRemover.cleanAsynchronously(now);<br> }<br>}<br><br>TimeBasedArchiveRemover.java
- public Future<?> cleanAsynchronously(Date now) {
- ArhiveRemoverRunnable runnable = new ArhiveRemoverRunnable(now);
- ExecutorService executorService = context.getScheduledExecutorService();
- Future<?> future = executorService.submit(runnable);
- return future;
- }<br>重点在这里：ArhiveRemoverRunnable。<br>这个类是内部类，用途是实现了个线程类，初看没啥问题，仔细想想，类的加载是有顺序的，有没有可能是这个内部类加载的时候，报错了？<br>好好的为啥加载不上了呢？谁动了他的奶酪？<br>各种检查、分析，发现了个奇怪的现象：<br>日志中打印的jar启动的时间是10点，然后jar包的最后修改时间是17点。什么鬼？难道是替换了新包没有重启，导致这个内部类加载有问题，系统宕机了？<br>抓紧验证一下，构造一个类似的场景：<br>1.修改系统时间为23:55:00.使用java -jar ***.jar启动服务。<br>2.准备个微调的jar包，待之前的服务启动好后，替换掉他，然后坐等零点到来。<br>3.激动人心的时刻到了，零点后，dev.log不见了，dev-2023-04-13.0.log有生成。抓紧看下控制台。一堆报错，最关键的信息也打印了。
- <em id="__mceDel"><img src="https://img2023.cnblogs.com/blog/3171906/202304/3171906-20230413113848906-1537632875.png" alt="" loading="lazy" ></em>
五、总结：
这个问题太邪门了，尤其是凌晨暴雷，简直是要了程序员的老命，果然不管什么问题，重启试试是最有效的武器。
本次系统宕机的问题就分享到这里，谢谢大家批评指正。
- timeBasedFileNamingAndTriggeringPolicy
|
