logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject DO NOT REPLY [Bug 51152] New: RollingFileAppender of companion/extras 1.1 contains possible race condition
Date Wed, 04 May 2011 22:30:06 GMT
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: log4j-dev@logging.apache.org
        ReportedBy: grave@gmx.de
    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: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message