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.
I suspect that it is socket: calling InternalNioOutputBuffer.recycle() twice will fail with NPE, because socket is set to null on the first call.
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
Created attachment 26549 [details] 2011-01-25_tc6_50651.patch Patch for 6.0.x.
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.
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)
(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
(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 ?
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.
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.
(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.
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).