Bug 43374 - DailyRollingFileAppender may lose messages during failed rollover
DailyRollingFileAppender may lose messages during failed rollover
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.2
PC Windows XP
: P2 critical
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2007-09-13 01:07 UTC by arnauldvm
Modified: 2011-03-10 08:07 UTC (History)
3 users (show)



Attachments
Patch solving the issue (8.25 KB, patch)
2007-09-13 01:08 UTC, arnauldvm
Details | Diff
Unit test reproducing the bug (11.71 KB, text/x-java-source)
2007-09-13 01:12 UTC, arnauldvm
Details
Patch solving the issue (1.07 KB, patch)
2007-09-13 02:19 UTC, arnauldvm
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description arnauldvm 2007-09-13 01:07:45 UTC
The DailyRollingFileAppender (DRFA) tries to rename the log file during roll over. 
However, when the rename fails, it ends up overwriting the log file, hence
loosing information.  In particular, on Windows, the file rename can fail if
another thread has the file open.

This problem was found in 1.2.8 and still exists in 1.2.15.

The problem was already described in bug 29726, but at that time the solution
was left to 1.3. Then it was again addressed in bug 41735, but only for
RollingFileAppender (RFA). I also talked about it on log4j-user ML
(http://mail-archives.apache.org/mod_mbox/logging-log4j-user/200709.mbox/%3cc8485ef10709040538k2074c3aag644f7b19a3a41e81@mail.gmail.com%3e).

I created a unit test that reproduces the problem (and also tests RFA), and made
a patch to solve this problem.

The problem was reproduced with both log4j 1.2.9 & 1.2.15 in the following
configurations (all combinations):
 - Win XP SP1, Win XP SP2, Win 2K3
 - JDK 1.4.2_03-b02, 1.5.0_10-b03, 1.6.0_02-b06
 - JUnit 3.8.1

The following patch applies on 1.2.15 and addresses the issue:
(I tested it in all the above configurations.)

Index: DailyRollingFileAppender.java
===================================================================
--- DailyRollingFileAppender.java	(revision 572567)
+++ DailyRollingFileAppender.java	(working copy)
@@ -319,16 +319,19 @@
 
     File file = new File(fileName);
     boolean result = file.renameTo(target);
+    boolean continueToAppend = false;
     if(result) {
       LogLog.debug(fileName +" -> "+ scheduledFilename);
     } else {
-      LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
+      //   if file rename failed, reopen file with append = true
+      LogLog.warn("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
+      continueToAppend = true;
     }
 
     try {
       // This will also close the file. This is OK since multiple
       // close operations are safe.
-      this.setFile(fileName, false, this.bufferedIO, this.bufferSize);
+      this.setFile(fileName, continueToAppend, this.bufferedIO, this.bufferSize);
     }
     catch(IOException e) {
       errorHandler.error("setFile("+fileName+", false) call failed.");
Comment 1 arnauldvm 2007-09-13 01:08:42 UTC
Created attachment 20806 [details]
Patch solving the issue
Comment 2 arnauldvm 2007-09-13 01:12:36 UTC
Created attachment 20807 [details]
Unit test reproducing the bug
Comment 3 arnauldvm 2007-09-13 02:19:58 UTC
Created attachment 20809 [details]
Patch solving the issue

(Cleaner version of the patch)
Comment 4 Curt Arnold 2007-09-19 11:36:54 UTC
Committed changes in rev 577413.

I could not come up with a scenario where it would be undesirable to append to
the base log file name, so instead of calculating whether to append based on
rename failure, I just hard-coded it to append.  I created a much simpler test
to add to the existing DRFATestCase that fails with the old code.

Changed the bug title since the DRFA is expected to delete files, but not to
lose messages.
Comment 5 Aditya Gujrathi 2010-11-12 02:04:35 UTC
There is a similar bug 44932, which is reported for log4j version 1.2.15. Does this fix also address the issue mentioned in the bug 44932? There is an issue we have for our application where in rare scenarios, the rollover files are getting deleted and our application starts writing to a single log file which then grows to over 50GB. We are using log4j version 1.2.15.
So I am not sure if we should move to the latest version 1.2.16 which has this fix or whether the due to issue mentioned in 44932 (which is still open), the application will continue to behave erratically at times.
Comment 6 bouliz 2010-11-12 15:54:44 UTC
(In reply to comment #5)
> There is a similar bug 44932, which is reported for log4j version 1.2.15. Does
> this fix also address the issue mentioned in the bug 44932? There is an issue
> we have for our application where in rare scenarios, the rollover files are
> getting deleted and our application starts writing to a single log file which
> then grows to over 50GB. We are using log4j version 1.2.15.
> So I am not sure if we should move to the latest version 1.2.16 which has this
> fix or whether the due to issue mentioned in 44932 (which is still open), the
> application will continue to behave erratically at times.

We have the same problem ! I think it could be solve issue 44932 but im not sure.