多进程使用同一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