Bug 46404 - NPE when logging an AxisFault with SocketAppender
NPE when logging an AxisFault with SocketAppender
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.2
All All
: P2 normal
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks: 43313
  Show dependency tree
 
Reported: 2008-12-16 01:36 UTC by Hanno Neuer
Modified: 2009-07-07 07:52 UTC (History)
0 users



Attachments
New Version of ThrowableInformation class (2.92 KB, text/x-java)
2009-02-25 07:37 UTC, Hanno Neuer
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Hanno Neuer 2008-12-16 01:36:33 UTC
Logging an org.apache.axis.AxisFault using the SimpleSocketServer results in a NullPointerException on the client side.

Versions: 
Log4J 1.2.15
Java 1.4.2_10
axis 1.4


Test method:
public static void main(String[] args) throws Exception {
  logger = Logger.getLogger(Test.class);
  logger.debug("start");
  logger.debug("err", new org.apache.axis.AxisFault());
}


Output on Client (in System.err):
log4j:WARN Detected problem with connection: java.io.IOException: stream active
java.lang.NullPointerException
	at org.apache.log4j.net.SocketAppender.append(SocketAppender.java:243)
	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.debug(Category.java:279)
	at Test.main(SAPEquipmentQueryClientTest.java:421)
Exception in thread "main" 



Output on Server's log:
2008-12-16 10:05:53,512 [main] INFO  net.SimpleSocketServer - Connected to client at /xxx.xxx.xxx.xxx
2008-12-16 10:05:53,514 [main] INFO  net.SimpleSocketServer - Starting new socket node.
2008-12-16 10:05:53,518 [main] INFO  net.SimpleSocketServer - Waiting to accept a new client.
2008-12-16 10:05:51,496 [main] DEBUG Test - start
2008-12-16 10:05:53,916 [Thread-98] INFO  net.SocketNode - Caught java.io.IOException: java.io.StreamCorruptedException
2008-12-16 10:05:53,917 [Thread-98] INFO  net.SocketNode - Closing connection.


Configuration Client:
log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
	<appender name="SimpleServerSocketLogger" class="org.apache.log4j.net.SocketAppender">
		<param name="remoteHost" value="host"/>
		<param name="port" value="4445"/>
		<param name="LocationInfo" value="true"/>
	</appender>
	<root>
		<priority value="debug"/>
		<appender-ref ref="SimpleServerSocketLogger"/>
	</root>
</log4j:configuration>


Configuration Server:
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
	<appender name="Konsole" class="org.apache.log4j.DailyRollingFileAppender">
		<param name="File" value="Java.log"/>
		<param name="DatePattern" value="'.'yyyy-MM-dd"/>
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d [%t] %-5p %C{2} - %m%n"/>
		</layout>
	</appender>
	<root>
		<priority value="debug"/>
		<appender-ref ref="Konsole"/>
	</root>
</log4j:configuration>
Comment 1 Curt Arnold 2009-01-08 09:28:38 UTC
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.
Comment 2 Hanno Neuer 2009-02-25 07:37:53 UTC
Created attachment 23307 [details]
New Version of ThrowableInformation class
Comment 3 Hanno Neuer 2009-02-25 07:39:54 UTC
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
Comment 4 QualityChecker 2009-02-25 08:03:50 UTC
For more details on NPE risks and others on log4j have a look here

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

Thanks
Comment 5 Curt Arnold 2009-02-25 11:59:54 UTC
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?
Comment 6 Hanno Neuer 2009-02-26 00:22:03 UTC
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
Comment 7 Curt Arnold 2009-04-07 20:54:50 UTC
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();
Comment 8 Hanno Neuer 2009-04-07 23:00:42 UTC
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.
Comment 9 Curt Arnold 2009-04-08 05:32:19 UTC
If that addresses the problem, you could like workaround the problem in previous versions by wrapping the SocketAppender in a AsyncAppender.
Comment 10 Richard Abbuhl 2009-04-08 09:07:09 UTC
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.
Comment 11 Richard Abbuhl 2009-04-20 01:35:19 UTC
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?
Comment 12 Curt Arnold 2009-05-11 21:46:39 UTC
Commited fixes in rev 773779.
Comment 13 Richard Abbuhl 2009-07-07 07:52:29 UTC
When will you create a log4j release which contains these commited fixes?