Bug 50651 - NPE in InternalNioOutputBuffer.recycle
NPE in InternalNioOutputBuffer.recycle
Status: RESOLVED FIXED
Product: Tomcat 6
Classification: Unclassified
Component: Catalina
6.0.30
PC Linux
: P2 major (vote)
: default
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2011-01-25 12:51 UTC by Éric Estièvenart
Modified: 2011-01-27 13:49 UTC (History)
0 users



Attachments
2011-01-25_tc6_50651.patch (680 bytes, patch)
2011-01-25 14:47 UTC, Konstantin Kolinko
Details | Diff
catalina.2011-01-27.log (4.15 KB, text/plain)
2011-01-26 19:45 UTC, Konstantin Kolinko
Details
2011-01-27_tc6_50651_CoyoteAdapter.patch (976 bytes, patch)
2011-01-26 20:38 UTC, Konstantin Kolinko
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Éric Estièvenart 2011-01-25 12:51:59 UTC
Note: this is a regression of 6.0.30, the problem does not appear in 6.0.29

36.567 [http-8080-exec-1] ERROR o.apache.tomcat.util.net.NioEndpoint - java.lang.NullPointerException: null
        at org.apache.coyote.http11.InternalNioOutputBuffer.recycle(InternalNioOutputBuffer.java:351) ~[tomcat-coyote.jar:6.0.30] 
           socket.getBufHandler().getWriteBuffer().clear();                                                                            
        at org.apache.coyote.http11.Http11NioProcessor.recycle(Http11NioProcessor.java:1007) ~[tomcat-coyote.jar:6.0.30]                                                                                                                   
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:643) ~[tomcat-coyote.jar:6.0.30]                                                                                              
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.event(Http11NioProtocol.java:679) ~[tomcat-coyote.jar:6.0.30]                                                                                                
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2262) ~[tomcat-coyote.jar:6.0.30]                                                                                                                   
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_21]    

Note sure yet whether it is the socket, its bufhandler or the buffer which is null.
Comment 1 Konstantin Kolinko 2011-01-25 13:07:00 UTC
I suspect that it is socket: calling InternalNioOutputBuffer.recycle() twice will fail with NPE, because socket is set to null on the first call.
Comment 2 Konstantin Kolinko 2011-01-25 14:37:22 UTC
To reproduce, with TC 6.0.31:
1. Configure Tomcat to use Nio connector.
2. Start Tomcat.
3. Connect to Tomcat HTTP port with a telnet client. Type "foo<Enter>".
4. Server replies with "HTTP/1.1 400 Bad Request". At the same time in the logs you can see two instances of NPE at
org.apache.coyote.http11.InternalNioOutputBuffer.recycle(InternalNioOutputBuffer.java:351)

7.0.x is not affected, thanks to r1022478
Comment 3 Konstantin Kolinko 2011-01-25 14:47:39 UTC
Created attachment 26549 [details]
2011-01-25_tc6_50651.patch

Patch for 6.0.x.
Comment 4 Filip Hanik 2011-01-25 16:25:36 UTC
What I don't like about patches like this, is that they don't address the regression, simply mitigate it.
If the problem has always existed, then fine, implement it.
But if this problem didn't exist in previous versions, then we're not fixing the actual regression.
Comment 5 ppan 2011-01-25 17:02:59 UTC
I was testing the sample code from http://www.ibm.com/developerworks/web/library/wa-cometjava/. 
Each time when the connection was closed, two END Comet events were received. The second one seems causing the NPE error. 

Jan 25, 2011 3:31:28 PM org.apache.catalina.core.ApplicationContext log
INFO: WeatherServlet: Begin for session: CF345C44A1C1040EC6C112B494A7E00C
Jan 25, 2011 3:31:28 PM org.apache.catalina.core.ApplicationContext log
INFO: WeatherServlet: Message added #messages=1
Jan 25, 2011 3:31:28 PM org.apache.catalina.core.ApplicationContext log
INFO: WeatherServlet: Closing connection
Jan 25, 2011 3:31:28 PM org.apache.catalina.core.ApplicationContext log
INFO: WeatherServlet: End for session: CF345C44A1C1040EC6C112B494A7E00C
Jan 25, 2011 3:31:28 PM org.apache.catalina.core.ApplicationContext log
INFO: WeatherServlet: End for session: CF345C44A1C1040EC6C112B494A7E00C
Jan 25, 2011 3:31:28 PM org.apache.tomcat.util.net.NioEndpoint$SocketProcessor run
SEVERE:
java.lang.NullPointerException
        at org.apache.coyote.http11.InternalNioOutputBuffer.recycle(InternalNioOutputBuffer.java:351)
        at org.apache.coyote.http11.Http11NioProcessor.recycle(Http11NioProcessor.java:1007)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:643)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.event(Http11NioProtocol.java:679)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2262)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
Comment 6 Konstantin Kolinko 2011-01-25 17:12:53 UTC
(In reply to comment #4)
Repeated calls to recycle() should succeed. Shouldn't they? Implementation of InternalNioOutputBuffer.recycle() was already broken in this sense earlier, since r428884.

What is different in 6.0.30 is that several new calls to recycle() appeared -- I remember of the one in [1], and thus this issue became apparent. The reproduction recipe in comment 2 is based on [1].

[1] http://svn.apache.org/viewvc/tomcat/tc6.0.x/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?r1=1030188&r2=1030187&pathrev=1030188
Comment 7 Filip Hanik 2011-01-26 14:20:26 UTC
(In reply to comment #6)
> (In reply to comment #4)
> Repeated calls to recycle() should succeed. Shouldn't they? Implementation of
> InternalNioOutputBuffer.recycle() was already broken in this sense earlier,
> since r428884.

not really, calling recycle multiple times is probably just a sign of bad code. Whether the recycle method should be idempotent is a separate discussion.
I agree that it should, but it doesn't mean it should be called multiple times.
Cause the bugs that come up from coding like that, is way harder to track down.


> 
> What is different in 6.0.30 is that several new calls to recycle() appeared --
> I remember of the one in [1], and thus this issue became apparent. The
> reproduction recipe in comment 2 is based on [1].
> 
> [1]
> http://svn.apache.org/viewvc/tomcat/tc6.0.x/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?r1=1030188&r2=1030187&pathrev=1030188

So, why not fix the real problem ?
Comment 8 Konstantin Kolinko 2011-01-26 19:45:54 UTC
Created attachment 26554 [details]
catalina.2011-01-27.log

(In reply to comment #7)
> Whether the recycle method should be idempotent is a separate discussion.
> I agree that it should, but it doesn't mean it should be called multiple times.
> Cause the bugs that come up from coding like that, is way harder to track down.

I am sure that if we skip recycling the processor before its reuse in some case, the consequences will be harder than if we recycle it twice.

The code is already hard to follow at some places. 

> So, why not fix the real problem ?

I think the bug in recycle() is the real problem. Though I do not mind patching CoyoteAdapter.log() as well. Part of the necessary changes is in r1059548 [2]

[2] http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java?r1=1059548&r2=1059547&pathrev=1059548


Here is one more occurrence of the issue,
just using the browser (Firefox 3.6.13):
1. Using Tomcat 6.0.31. Configure Tomcat with Http11NioProtocol connector and AccessLogValve in <Host>
2. Clear cache of the browser
3. Access http://localhost:8080/examples/jsp/plugin/plugin.jsp
4. Wait for more than 10 seconds.
5. The pair of exceptions occur:

27.01.2011 3:09:37 org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler process
SEVERE: Error reading request, ignored
java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.recycle(InternalNioOutputBuffer.java:351)
	at org.apache.coyote.http11.Http11NioProcessor.recycle(Http11NioProcessor.java:1007)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:655)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:751)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2262)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
27.01.2011 3:09:37 org.apache.tomcat.util.net.NioEndpoint$SocketProcessor run
SEVERE: 
java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.recycle(InternalNioOutputBuffer.java:351)
	at org.apache.coyote.http11.Http11NioProcessor.recycle(Http11NioProcessor.java:1007)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:655)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:776)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2262)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

-- see attachment.

Access log:
127.0.0.1 - - [27/Jan/2011:03:09:26 +0300] "GET /examples/jsp/plugin/plugin.jsp HTTP/1.1" 200 1655
127.0.0.1 - - [27/Jan/2011:03:09:26 +0300] "GET /favicon.ico HTTP/1.1" 200 21630
127.0.0.1 - - [27/Jan/2011:03:09:27 +0300] "GET /examples/jsp/plugin/applet/Clock2.class HTTP/1.1" 304 -

I am not able to reproduce this with usual static or JSP pages.

I suspect that some cause is that Http11NioProtocol#process(NioChannel) there are calls to release(socket, processor) in "if (state == SocketState.OPEN)" and in "else" branches -- Http11NioProtocol.java:751 is where the exception occurs,  but Http11NioProcessor#process(NioChannel) called from there already calls recycle() by itself.

I think this comes from r1030613. There were later changes in Http11NioProcessor to add to this.


The second exception in the pair, at (Http11NioProtocol.java:776) occurs after a catch block. This comes from r1033341. In this place it is hard to guess whether recycle() call already happened or not.


The reproduction recipe in comment 5 is different from the both of mine ones.
Comment 9 Konstantin Kolinko 2011-01-26 20:38:58 UTC
Created attachment 26557 [details]
2011-01-27_tc6_50651_CoyoteAdapter.patch

Patch, in addition to the previous one:
Recycle request and response in CoyoteAdapter#log() only if they were created there.
Comment 10 Filip Hanik 2011-01-27 11:24:16 UTC
(In reply to comment #9)
> Created an attachment (id=26557) [details]
> 2011-01-27_tc6_50651_CoyoteAdapter.patch
> 
> Patch, in addition to the previous one:
> Recycle request and response in CoyoteAdapter#log() only if they were created
> there.

+1 to this one.
Comment 11 Konstantin Kolinko 2011-01-27 13:49:54 UTC
Both patches were applied and will be in 6.0.32.

As I mentioned, the same changes to TC7 are already applied in r1022478 (7.0.4) and r1059548 (-> 7.0.7).