多進程使用同一log4j配置導致的日志丟失與覆蓋問題

最近接手了一個流傳很多手的魔性古早代碼，追日志時發現有明顯缺失。對log4j不熟，不過可以猜測日志出問題肯定和多進程使用同一個log4j配置有關。經多次排查，終於捋清了其中邏輯。本文對排查過程進行復盤。

 

一、表征

故事背景：項目有多個入口。一邊即以持續運行獲取消息的后台進程形式運行，一邊又作為單次任務調度的普通進程被不斷啟動並結束退出。也就是說，同一個項目同時運行着多個進程，並且使用着同一個log4j配置。

下面稱后台進程為進程A，普通進程為進程B。A在后台持續運行，B多次短暫執行。

|<----------------- A ------------------- ...... 
  |<- B ->|    |<--- B --->|   |<- B ->|

 

起因：進程B的運行效果與預計不符，需排查B的日志定位問題。

神奇的現象：

1）有的B有日志有的沒有，沒發現明顯的出現規律。

2）有的B日志完整，有的不完整。

3）只有近幾個小時的B有日志，寫進文件的B的日志居然過一段時間會消失。

4）歷史日志中，絕大多數日期只有一個B的日志，而個別日志有很多。

 

 

二、內因

每一個A/B的日志指針都分別以append方式打開日志文件，文件指針互相獨立，各自向后寫。從而導致兩個問題：

問題1：因A寫的慢、B寫的快（業務實際情況），所以每一個B均在文件末尾append，和上一B相鄰，而A會逐漸覆蓋B的日志，直到開始滾動分頁。

 

問題2：當切換到下一自然日0點時，開始滾動分頁時，如果此時有B正在運行，則A和B各自有一個指針。

參考 https://blog.csdn.net/somechange/article/details/80895507 所說。

如果A先寫，則兩次滾動分頁后，A往log.yesterday中寫，而B往log中寫，並在任務完成后釋放句柄並退出。新的B繼續在log中寫。

如果B先寫，則兩次滾動分頁后，A往log中寫，B往log.yesterday中寫，並在任務完成后釋放句柄並退出。新的B繼續在log中寫。

無論如何，真正的log.yesterday都已經被覆蓋。

 

 

	day1	day2	day3	day4	day5	day6
假設		A先寫	A先寫	B先寫	B先寫	A先寫
log	day1的A+B	day2的B	day3的B	day4的A+其他B	day5的A+其他B	day6的B
log.day1		day2的A	day2的A	day2的A	day2的A	day2的A
log.day2			day3的A	day3的A	day3的A	day3的A
log.day3				day4的第一個B	day4的第一個B	day4的第一個B
log.day4					day5的第一個B	day5的第一個B
log.day5						day6的A

 

D日（D <= T-2）的日志只有四種情況：（T日即當前日期）

① 記錄了D+1日的第一個B（因為D+1日有B跨天，且B先寫）

② 記錄了D+1日的所有A（因為D+1日有B跨天，且A先寫）

③ 記錄了D日的所有A+ 未被覆蓋的B（因為D+1日沒有B跨天，且D日B先寫）

④ 記錄了D日的所有的非首個B（因為D+1日沒有B跨天，且D日A先寫）

 

符合觀察到的現象。

done