https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
Bug #: 51152
Summary: RollingFileAppender of companion/extras 1.1 contains
possible race condition
Product: Log4j
Version: 1.2
Platform: PC
Status: NEW
Severity: normal
Priority: P2
Component: Other
AssignedTo: [email protected]
ReportedBy: [email protected]
Classification: Unclassified
Hi.
I'm using log4j 1.2.16 with the companion/extras 1.1 package to allow rolling
files based on time (at midnight) and perform gz compression. I also use an
non-blocking AsyncAppender that delegates to SMTPAppender, and FileAppender.
System:
- Quadcore Xeon 2,33 Ghz
- JDK 1.5.0_15
- about 20 custom parallel working threads
- about 800-1000mb log file per day
I encountered a strange behavior on that system, that compression sometimes
isn't performed. The file is renamed correctly though (from mylog.log to
mylog.log.yyyy-MM-dd).
I looked at the asynchronous GZCompressionAction and its superclass
ActionBase. ActionBase calls execute() on the subclass when run() is invoked.
But I found out, that sometimes execute() isn't called due to this code:
public synchronized void run()
{
if(!interrupted)
{
Interrupted is set by the close() method. So looking for an invocation of
close() I came across RollingFileAppender:
http://grepcode.com/file/repo1.maven.org/maven2/log4j/apache-log4j-extras/1.1/org/apache/log4j/rolling/RollingFileAppender.java/
Here's where the race condition seems to happen. Debugging revealed, that in
that special case close() is invoked BEFORE run() is called - interrupting the
compression before it has even started.
Looking at:
...
313: if (rollover.getAsynchronous() != null) {
314: lastRolloverAsyncAction = rollover.getAsynchronous();
315: new Thread(lastRolloverAsyncAction).start();
316: }
...
which is protected by a synchronized block, starts a new Thread
(GZCompressionAction). But start()ing doesn't neccessarily mean that
run() is invoked immediately! So when the synchronized block is left,
lastRolloverAsyncAction is open to be interrupted by a parallel close() call
done by this code earlier:
224: synchronized (this) {
225: //
226: // if a previous async task is still running
227: //}
228: if (lastRolloverAsyncAction != null) {
229: //
230: // block until complete
231: //
232: lastRolloverAsyncAction.close();
...
So at this point, before run() even gets invoked by the JVM, close() has
"interrupted" the GZCompressAction (more specific the ActionBase).
I hope somebody could follow me and can confirm this.
I tried to create a test case but it seems really hard to reproduce this.
As soon as I have one, I'll let you know.
In the meantime, maybe someone can take a look at this.
Thanks.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
