Bug 46404

Problem was not obvious on code review.  Marking this as a blocker for log4j 1.2.16.  Would appreciate a patch or more analysis if available.  If not, will try to revisit after walking through the bug list.

Created attachment 23307 [details]
New Version of ThrowableInformation class

After further investigations I was able to track down the problem. The AxisFault class itself tries to make logging statements when its 'printStackTrace' method is called.
I changed the ThrowableInformation class to create the string representation of the Throwable in the constructor, so when the information is needed while logging is done no further call to 'printStackTrace' is neccessary which solves the above problem.

Please review the changes, the new version of the class is in the attachment.


Regards,
Hanno

For more details on NPE risks and others on log4j have a look here

http://www.qualitesys.com/wswebconsulterfichiers.php?projet=demojava_log4j

Thanks

Pushing the call to printStackTrace into the constructor is not acceptable from a performance standpoint since the call could be fairly expensive and might never be needed.

This problem may be another manifestation of bug 44038 and the fix for it may have addressed the problem.  There was not sufficient information in the original report to know if it was the same or different problem.  Could you retest using the SVN HEAD and see if the fix for bug 44038 addressed the problem?

My further analysis:
The problem is not related to bug 44038 and exists not only for Exceptions but for all Objects. 

Assume the following lines and a SocketAppender configuration:

    logger.debug(new Object() {
      public String toString() {
        Logger.getLogger(Object.class).debug("Will not go through the wire");
        return "Will not go through the wire neither!";
      }
    });


The problem is in SocketAppender#append(LoggingEvent) in combination with the LoggingEvent serialization.

SocketAppender#append(LoggingEvent) will call ObjectOutputStream#writeObject with the given LoggingEvent. In ObjectOutputStream#writeObject the underlying OutputStream will be prepared and then at some point LoggingEvent#writeObject(ObjectOutputStream) will be called.

In LoggingEvent#writeObject(ObjectOutputStream) there are a few lines preparing the non-transient fields of LoggingEvent, e.g. getRenderedMessage and getThrowableStrRep. Those methods make calls to the Object and Throwable to be logged which are not restricted in anyway. And that's the crux of the matter, they can even have their own logging!

If now the Object to be logged (as in the above example) calls the Logger again, it will try to send a second LoggingEvent through the wire using the same ObjectOutputStream, allthough the ObjectOutputStream is currently used to write the first LoggingEvent.

This results in:
log4j:WARN Detected problem with connection: java.io.IOException: stream active


A possible solution to handle this situation is to make sure, that the LoggingEvent will not make any calls to the logged Objects while serialization (e.g. by preparing the LoggingEvent _before_ ObjectOutputStream#writeObject is called).

I hope this clarifies my problem.

Hanno

Could anyone who has this problem check if the following patch resolves the issue.  Basically, it forces the evaluation of the message's toString() and the exception if any's printStackTrace() to occur before the start of writeObject().


Index: src/main/java/org/apache/log4j/net/SocketAppender.java
===================================================================
--- src/main/java/org/apache/log4j/net/SocketAppender.java	(revision 746252)
+++ src/main/java/org/apache/log4j/net/SocketAppender.java	(working copy)
@@ -244,6 +244,8 @@
     if (application != null) {
         event.setProperty("application", application);
     }
+    event.getRenderedMessage();
+    event.getThrowableStrRep();
 	oos.writeObject(event);
 	//LogLog.debug("=========Flushing.");
 	oos.flush();

Thanks for looking into this.

This patch solves the problem for the SocketAppender but it will remain for other appenders.

Two appenders which I manually checked for the problem (allthough I didn't try to run the code):
  - SocketHubAppender (also uses ObjectOutputStream, same as in SocketAppender)
  - JDBCAppender (should result in a ConcurrentModificationException while flushing the buffer)

I haven't looked into other appenders beside these two, but I assume there will be more places where the problem occurs.

A more general solution is to make sure that the two lines
 +    event.getRenderedMessage();
 +    event.getThrowableStrRep();
are called before the actual call to AppenderSkeleton#append is done in AppenderSkeleton#doAppend. 

I am not sure about the performance or other impacts of this solution so I want you Log4j guys to check it for feasibility.

If that addresses the problem, you could like workaround the problem in previous versions by wrapping the SocketAppender in a AsyncAppender.

I applied the patch suggested in Comment #7 to the 1.2.15 Java source and created a new jar file log4j-1.2.15.1.  Locally, on my development system the patch seems to prevent the NullPointerException on the client side.  This new jar needs to be deployed on our test system for further validation.

The jar file log4j-1.2.15.1 was deployed on our test system and it seems to be a valid solution.  When can we expect an official release from Apache which contains this fix?

Commited fixes in rev 773779.

When will you create a log4j release which contains these commited fixes?