Bug 51783 - WriterAppender NullPointerException when calling close and append concurrently
Summary: WriterAppender NullPointerException when calling close and append concurrently
Status: NEW
Alias: None
Product: Log4j - Now in Jira
Classification: Unclassified
Component: Appender (show other bugs)
Version: 1.2
Hardware: PC Linux
: P2 major
Target Milestone: ---
Assignee: log4j-dev
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-09-07 23:49 UTC by Adrian Nistor
Modified: 2011-09-07 23:52 UTC (History)
1 user (show)



Attachments
test (937 bytes, text/x-java)
2011-09-07 23:49 UTC, Adrian Nistor
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Adrian Nistor 2011-09-07 23:49:30 UTC
Created attachment 27471 [details]
test

Hi,

I am encountering a NullPointerException in WriterAppender. I am using
Log4j version 1.2.16. 

The NullPointerException manifests when calling close() and append()
concurrently. I have attached a test that exposes this problem. For 
this test, the expected output is:

Expected output:
0
1
2
3
4
.....
499998
499999
DONE

But when the bug manifests (almost always for this test), the output 
is:

Bug output:
0
1
2
3
4
...
16
Exception in thread "main" java.lang.NullPointerException
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:317)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.Test.test(Test.java:37)
    at org.apache.log4j.Test.main(Test.java:16)

or

0
1
2
3
4
Exception in thread "main" java.lang.NullPointerException
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:318)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.Test.test(Test.java:37)
    at org.apache.log4j.Test.main(Test.java:16)

The test iteration where the NullPointerException is thrown varies
from run to run, depending on how the threads interleave.

The reason for NullPointerException is that append() is not 
synchronized. 

Here is the thread scenario that triggers the bug:
(1) append() starts to execute. It checks checkEntryConditions(). This
    check succeeds because close was not yet executed(). append() 
    continue to subAppend(event); but does not yet enter subAppend()
    (e.g., if there is a delay due to high load)
(2) the other thread executes close(). close() calls reset() which
    sets this.qw = null;
(3) append() continue to execute subAppend(); subAppend() calls 
    several methods on this.qw, which by now is null. These methods
    are:
        this.qw.write(this.layout.format(event));
        this.qw.write(s[i]);
        this.qw.write(Layout.LINE_SEP);
    Calling these methods throws NullPointerException.

The solution is to synchronize append(). close() is already 
synchronized.

Is this a bug? Does synchronizing append() fully solve the problem?
Are there other scenarios that I am missing and are not solved by
synchronizing append()?

Thanks!

Adrian