Bug 49884 - NullPointerException in org.apache.catalina.core.AsyncContextImpl.doInternalComplete
NullPointerException in org.apache.catalina.core.AsyncContextImpl.doInternalC...
Status: RESOLVED FIXED
Product: Tomcat 7
Classification: Unclassified
Component: Catalina
trunk
PC All
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-09-04 23:16 UTC by Kevin
Modified: 2010-09-27 08:14 UTC (History)
1 user (show)



Attachments
Servlet used to reproduce the problem (1.57 KB, text/x-java)
2010-09-04 23:24 UTC, Kevin
Details
Patch to make some private fields final (1.77 KB, patch)
2010-09-13 12:13 UTC, Sebb
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Kevin 2010-09-04 23:16:09 UTC
Hi, I'm running Tomcat trunk (revision 992708, 2010-09-03) and I'm hitting an async servlet (see attached) with Apache Bench, and every once in a while I see a NullPointerException in org.apache.catalina.core.AsyncContextImpl.doInternalComplete:

Sep 4, 2010 8:09:39 PM org.apache.catalina.core.AsyncContextImpl doInternalDispatch
FINE: TIMING OUT!
Sep 4, 2010 8:09:40 PM org.apache.catalina.core.AsyncContextImpl doInternalDispatch
FINE: TIMING OUT!
Sep 4, 2010 8:09:40 PM org.apache.catalina.core.AsyncContextImpl doInternalComplete
SEVERE: 
Throwable occurred: java.lang.NullPointerException
	at org.apache.catalina.core.AsyncContextImpl.doInternalComplete(AsyncContextImpl.java:384)
	at org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:327)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:238)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:201)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:163)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:108)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:557)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:301)
	at org.apache.coyote.http11.Http11Processor.asyncDispatch(Http11Processor.java:333)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:258)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:257)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:898)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:920)
	at java.lang.Thread.run(Thread.java:736)
Comment 1 Kevin 2010-09-04 23:24:22 UTC
Created attachment 25989 [details]
Servlet used to reproduce the problem
Comment 2 Mark Thomas 2010-09-05 17:10:09 UTC
The state changes in AsyncContextImpl aren't atomic so I think what you are seeing is the result of multiple parallel calls to doInternalComplete(). Am I correct in thinking this error is fairly rare?
Comment 3 Kevin 2010-09-05 17:42:02 UTC
(In reply to comment #2)
> The state changes in AsyncContextImpl aren't atomic so I think what you are
> seeing is the result of multiple parallel calls to doInternalComplete(). Am I
> correct in thinking this error is fairly rare?

Yes, it is rare. The reason I reported this is that I'm load testing this servlet (well, my real servlet, but this one just to repro the problem), and every once in a while I get a 200 or 500 response that takes over 10 seconds whereas the average is half a second (using AccessLogValve %D to see this). I ran with tracing and noticed this NPE and thought maybe it's somehow related to the sporadic long request, but I don't know if it's root cause. Also, it is preceded by the "TIMING OUT!" entry, so maybe this NPE is just a side effect of the timeout?
Comment 4 Mark Thomas 2010-09-07 09:03:57 UTC
I've been able to spend some time looking at this. It is very easy to reproduce on a multi-core machine with relatively low numbers of requests and concurrency.

There is definitely a threading issue at the heart of this. I need to dig deeper to find out exactly what the root cause is.
Comment 5 Kevin 2010-09-07 10:46:43 UTC
(In reply to comment #4)
> I've been able to spend some time looking at this. It is very easy to reproduce
> on a multi-core machine with relatively low numbers of requests and
> concurrency.
> 
> There is definitely a threading issue at the heart of this. I need to dig
> deeper to find out exactly what the root cause is.

Thanks Mark.
Comment 6 Sebb 2010-09-13 12:13:42 UTC
Created attachment 26022 [details]
Patch to make some private fields final

They are probably not a cause of the synch. issues, but it would not harm to make these fields final.
Comment 7 Mark Thomas 2010-09-27 08:14:41 UTC
This has been fixed in trunk and will be included in 7.0.3. Thanks for uncovering this. It highlighted a bunch of issues with the async implementation that are hopefully now fixed.