多进程使用同一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各自有一个指针。
如果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
原文地址:https://www.cnblogs.com/desertfish/p/11973161.html