You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by bu...@apache.org on 2004/05/10 17:02:28 UTC
DO NOT REPLY [Bug 17201] -
DailyRollingFileAppender and multi-instance loses data
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
srevilak@f7.net changed:
What |Removed |Added
----------------------------------------------------------------------------
Summary|DailyRollingFileAppender and|DailyRollingFileAppender and
|multi-instance |multi-instance loses data
------- Additional Comments From srevilak@f7.net 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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org