DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT <http://issues.apache.org/bugzilla/show_bug.cgi?id=17201>. ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND INSERTED IN THE BUG DATABASE.
http://issues.apache.org/bugzilla/show_bug.cgi?id=17201 DailyRollingFileAppender and multi-instance loses data [EMAIL PROTECTED] changed: What |Removed |Added ---------------------------------------------------------------------------- Summary|DailyRollingFileAppender and|DailyRollingFileAppender and |multi-instance |multi-instance loses data ------- Additional Comments From [EMAIL PROTECTED] 2004-05-10 15:02 ------- I too have found problems with DailyRollingFileAppender where multiple processes are writing to the same logfile, across the time boundary of a rotation period. The ultimate result is data loss, and it is easily reproducible. Accompanying this writeup are four file attachments: the first three comprise a test case to demonstrate this behavior; the fourth file is a patch to DailyRollingFileAppender that prevents this data loss. Test case files: 1) log4j.properties - Configures log4j with a DailyRollingFileAppender, whose rotation period is one minute, writing to a file named "test.log". 2) LogLoop.java - A command line java program. LogLoop takes arguments of M and N. It logs M info lines, spaces at N-second intervals, followed by "done". 3) runtest.sh - Bourne shell script that runs the test case. runtest.sh invokes three concurrent LogLoop instances * instance #1 logs 300 lines, at 1 second intervals + "done" * instance #2 logs 150 lines, at 2 second intervals + "done" * instance #3 logs 100 lines, at 3 second intervals + "done" Prior to the first rotation, test.log looks something like the following: 20040510.100541 INFO [main] LogLoop - log: 0 of 300 (interval=1) 20040510.100541 INFO [main] LogLoop - log: 0 of 100 (interval=3) 20040510.100541 INFO [main] LogLoop - log: 0 of 150 (interval=2) 20040510.100542 INFO [main] LogLoop - log: 1 of 300 (interval=1) 20040510.100543 INFO [main] LogLoop - log: 2 of 300 (interval=1) 20040510.100543 INFO [main] LogLoop - log: 1 of 150 (interval=2) 20040510.100544 INFO [main] LogLoop - log: 3 of 300 (interval=1) 20040510.100544 INFO [main] LogLoop - log: 1 of 100 (interval=3) The entries from the three processes are intermixed in the same file - just what one would expect. After the 5 minute test, one can aggregate the "interval=" entries across all of the test.log.* files. Below is the aggregation from one sample run: # of interval=1: 0 # of interval=2: 141 # of interval=3: 14 We would expect a total of 553 entries (300 + 150 + 100 + 1 + 1 + 1). Above, there are only 155. In other words, roughly two-thirds of the data has been lost. These results will vary non-deterministically among different runs, but any single run will produce data loss -- one process wins, while the other two lose. Admittedly, unsynchronized writes by independant processes are not ideal. However, for cases where this is seen as acceptable (eg - one recognizes the possibility of the occassionally corrupt log entry), I would maintain that a logging system should make reasonable attempts to prevent the loss of large portions of data. The attachment "DailyRollingFileAppender.java.patch" contains a patch with changes to rollover(). With this patch applied, the aggregation of logs from runtest.sh is as follows: # of interval=1: 301 # of interval=2: 151 # of interval=3: 101 All 553 entries present. I hope that you'll consider incorporating these changes into the next release of log4j. -- Steve Revilak --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
