一、事件背景：
某天凌晨，一陣急促的鈴聲將我從周公那里拉了過來，接聽電話后，一臉懵逼，
什么情況？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" >
<!-- 正在記錄的日志檔案的路徑及檔案名 -->
<file>${log.path}/dev.log</file>
<rollingPolicy background-color: rgba(0, 255, 255, 1)">TimeBasedRollingPolicy">
<!-- 日志歸檔 -->
<fileNamePattern>${log.path}/dev/dev-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy background-color: rgba(0, 255, 255, 1)">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
轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/549966.html
標籤：其他