Bug 44032 - ThrowableInformation.getThrowableStringRep() can return null lines.
ThrowableInformation.getThrowableStringRep() can return null lines.
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.2
Other other
: P2 normal
: ---
Assigned To: log4j-dev
: PatchAvailable
: 23019 45825 (view as bug list)
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2007-12-06 05:47 UTC by Ulrich Voigt
Modified: 2014-02-17 13:43 UTC (History)
3 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Ulrich Voigt 2007-12-06 05:47:05 UTC
I've got the following NullPointerException:

java.lang.NullPointerException
	at java.io.Writer.write(Writer.java:126)
	at org.apache.log4j.helpers.CountingQuietWriter.write(CountingQuietWriter.java:45)
	at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:309)
	at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:263)
	at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
	at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
	at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
	at org.apache.log4j.Category.callAppenders(Category.java:206)
	at org.apache.log4j.Category.forcedLog(Category.java:391)
	at org.apache.log4j.Category.warn(Category.java:1060)
	at ..... my classes .....

I guess that the message I wanted to log was != null and was logged correctly.
Comment 1 Ulrich Voigt 2007-12-06 06:04:25 UTC
I forgot to mention that the problem occured with version 1.2.15.
Comment 2 Peter Kormos 2008-01-15 07:03:57 UTC
We had a similar problem.

The problem is that we use an AsynchAppender and a SocketAppender for logging.
Because of how AsynchAppender works, it is possible that 
ThrowableInformation.getThrowableStrRep() runs on one LoggingEvent at the same time.

  public
  String[] getThrowableStrRep() {
    if(rep != null) {
      return (String[]) rep.clone();
    } else {
      StringWriter sw = new StringWriter();
      PrintWriter pw = new PrintWriter(sw);
      throwable.printStackTrace(pw);
      pw.flush();
      LineNumberReader reader = new LineNumberReader(
              new StringReader(sw.toString()));
      ArrayList lines = new ArrayList();
      try {
        String line = reader.readLine();
        while(line != null) {
          lines.add(line);
          line = reader.readLine();
        }
      } catch(IOException ex) {
          lines.add(ex.toString());
      }
      rep = new String[lines.size()];
      lines.toArray(rep);
    }
    return rep;
  }

The problem is with ThrowableInformation.rep. 
If the first concurrent thread gets only to rep = new String[lines.size()];
and then the next concurrent thread gets to if(rep != null),
then only rep.clone(); is returned with an empty array.

Then later concurrent thread #1 will fill up the array but that's already late
for the another concurrent thread.

I think in this case the solution would be either to 

a) synchronize on ThrowableInformation.getThrowableStrRep() or 
b) modify
      rep = new String[lines.size()];
      lines.toArray(rep);

in method with

      String[] tempRep = new String[lines.size()];
      lines.toArray(tempRep);
      rep = tempRep;

Comment 3 Ulrich Voigt 2008-01-16 09:44:27 UTC
The solution looks good to me. I prefer solution b) because I cannot estimate
the overall impacts of solution a).

My problem is that the bug occurs very rarely. I got only two cases in 2 months.
So I could not say for sure that the patch fixes the problem :-(

Anyhow: Can someone please commit the patch?
Comment 4 Curt Arnold 2008-01-17 08:57:37 UTC
Changed summary of bug since bug is not specific to RollingFileAppender.  

Changes committed in rev 612863.  

In addition to the synchronization issue, there was an isolation issue.  On every call except the first, the 
cached string representation was cloned before being returned.  However, if you got the first call, you 
could "rewrite" the string representation by modifying the returned value.  
ThrowableInformationTest.testIsolation would fail with log4j 1.2.15.  Whatever it did, it should have been 
consistent.  Either everyone should be able to rewrite or no one should be able to rewrite.
Comment 5 Ulrich Voigt 2008-05-21 08:00:37 UTC
*** Bug 23019 has been marked as a duplicate of this bug. ***
Comment 6 Curt Arnold 2008-09-17 09:12:17 UTC
*** Bug 45825 has been marked as a duplicate of this bug. ***
Comment 7 greg.jos 2010-03-18 15:26:02 UTC
Is there any workaround to this and/or an ETA for 1.2.16 ?