多进程log4j日志丢失问题分析

转自：http://hellojavaer.iteye.com/blog/977599

一、背景：后台有很多任务，每个任务都是一个main函数（JVM或进程），但是所有的任务都加载同一个log4j.xml文件，即往同一份文件中输出日志。

二、原因追踪：

在 log4j 的 DailyRollingFileAppender 类中：

Java代码  

1. void rollOver() throws IOException {  
2.   
3.     /* Compute filename, but only if datePattern is specified */  
4.     if (datePattern == null) {  
5.       errorHandler.error("Missing DatePattern option in rollOver().");  
6.       return;  
7.     }  
8.   
9.     String datedFilename = fileName+sdf.format(now);  
10.     // It is too early to roll over because we are still within the  
11.     // bounds of the current interval. Rollover will occur once the  
12.     // next interval is reached.  
13.     if (scheduledFilename.equals(datedFilename)) {  
14.       return;  
15.     }  
16.   
17.     // close current file, and rename it to datedFilename  
18.     this.closeFile();  
19.   
20.     File target  = new File(scheduledFilename);  
21.     if (target.exists()) {  
22.       target.delete();  
23.     }  
24.   
25.     File file = new File(fileName);  
26.     boolean result = file.renameTo(target);  
27.     if(result) {  
28.       LogLog.debug(fileName +" -> "+ scheduledFilename);  
29.     } else {  
30.       LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");  
31.     }  
32.   
33.     try {  
34.       // This will also close the file. This is OK since multiple  
35.       // close operations are safe.  
36.       this.setFile(fileName, false, this.bufferedIO, this.bufferSize);  
37.     }  
38.     catch(IOException e) {  
39.       errorHandler.error("setFile("+fileName+", false) call failed.");  
40.     }  
41.     scheduledFilename = datedFilename;  
42. }  

该方法的作用是：在滚动备份时间间隔到的时刻，将前一时间间隔的日志备份，同时以非追加模式将新日志打到新日志文件中；

中间部分代码意思是：如果备份文件不存在，则备份，同时创建新日志文件；如果存在，则先删除掉，再备份；

 

好，问题在这个时刻就出现了：（假设A进程先进行滚动备份）

1、对于A进程：
a. 先将 project.log备份（ renameTo()）为 project.log.2009.08.18，然后创建 project.log文件，并将日志写在 project.log中；
b. 此时A进程持有 project.log的文件句柄；而B进程仍然持有 project.log.2009.08.18的文件句柄（尽管被重命名，但句柄不变）；

2、对于B进程：发现以project.log.2009.08.18为文件名的文件已经存在，则将其删除（前一时间段的所有日志全没了），并将以project.log为文件名的文件重命名为project.log.2009.08.18，然后创建project.log文件；

3、此时A进程持有project.log.2009.08.18的文件句柄（被B进程重命名过的），而B进程持有最新创建的project.log；

4、结果导致：前一时间段日志丢失，A、B进程在不同的文件里打日志；

三、解决方案

1、改变 rollOver() 方法的实现方式：定义 TaskDailyRollingFileAppender 类，该类继承至 FileAppender ，它与 DailyRollingFileAppender 的主要区别在于以下方法：

Java代码  

1. void rollOver() throws IOException {  
2.   
3.     /* Compute filename, but only if datePattern is specified */  
4.     if (datePattern == null) {  
5.       errorHandler.error("Missing DatePattern option in rollOver().");  
6.       return;  
7.     }  
8.   
9.     String datedFilename = fileName+sdf.format(now);  
10.     // It is too early to roll over because we are still within the  
11.     // bounds of the current interval. Rollover will occur once the  
12.     // next interval is reached.  
13.     if (scheduledFilename.equals(datedFilename)) {  
14.       return;  
15.     }  
16.   
17.     // close current file, and rename it to datedFilename  
18.     this.closeFile();  
19.   
20.     File target  = new File(scheduledFilename);  
21.     if (!target.exists()) {  
22.         File file = new File(fileName);  
23.         boolean result = file.renameTo(target);  
24.         if (result) {  
25.             LogLog.debug(fileName + " -> " + scheduledFilename);  
26.         } else {  
27.             LogLog.error("Failed to rename [" + fileName + "] to [" + scheduledFilename + "].");  
28.         }  
29.     }  
30.   
31.     try {  
32.         // This will also close the file. This is OK since multiple  
33.         // close operations are safe.  
34.         this.setFile(fileName, true, this.bufferedIO, this.bufferSize);  
35.     }  
36.     catch(IOException e) {  
37.       errorHandler.error("setFile("+fileName+", false) call failed.");  
38.     }  
39.     scheduledFilename = datedFilename;  
40. }  

改进后的  rollOver() 方法主要作用是：A进程先将日志重命名，然后创建新日志文件，B进程发现已经存在，则直接以追加模式切换到新的日志文件上去；

 

2、如果是任务，根据启动参数taskName 属性区分日志文件：

a. 目前所有后台任务在启动脚本里都加上了 -DtaskName 属性；
b. 定义 TaskDailyRollingFileAppender 类，该类继承 DailyRollingFileAppender，并覆盖其 setFile(String file) 方法：

Java代码  

1. public void setFile(String file) {  
2.     String taskName = System.getProperty("taskName");  
3.     if (!StringUtil.isEmpty(taskName)) {  
4.         file = file + "." + taskName;  
5.     }  
6.   
7.     super.setFile(file);  
8. }  

  c. 这样实现后，对于不同的任务，日志文件名会以 .taskName结尾，对于没有指定  taskName 的任务，不受影响；