Bug 52009 - NPE exception in org.apache.catalina.connector.CoyoteAdapter.service
NPE exception in org.apache.catalina.connector.CoyoteAdapter.service
Status: RESOLVED FIXED
Product: Tomcat 7
Classification: Unclassified
Component: Connectors
7.0.22
PC Windows XP
: P2 major (vote)
: ---
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2011-10-11 08:06 UTC by viola.lu
Modified: 2011-10-17 03:35 UTC (History)
0 users



Attachments
tomcat configuration (4.52 KB, application/xml)
2011-10-12 03:07 UTC, viola.lu
Details

Note You need to log in before you can comment on or make changes to this bug.
Description viola.lu 2011-10-11 08:06:49 UTC
1. I copied activemq-all-5.4.2.jar, commons-logging-1.1.jar to tomcat lib folder
2. Edit tomcat-user.xml, context.xml, server.xml as below:

Changes  in server.xml:

<Resource  name="jms/broker" auth="Container" 
        type="org.apache.activemq.ActiveMQConnectionFactory" description="JMS Connection Factory"
        factory="org.apache.activemq.jndi.JNDIReferenceFactory" brokerURL="tcp://localhost:61616" brokerName="ActiveMQBroker" useEmbeddedBroker="false" />
        
    <Resource name="jms/topic/MyTopic" auth="Container" type="org.apache.activemq.command.ActiveMQTopic" factory="org.apache.activemq.jndi.JNDIReferenceFactory" physicalName="APP.JMS.TOPIC" />

<Resource name="jms/queue/MyQueue" auth="Container" type="org.apache.activemq.command.ActiveMQQueue" factory="org.apache.activemq.jndi.JNDIReferenceFactory" physicalName="APP.JMS.QUEUE" />


<Connector acceptorThreadPriority="1" allowTrace="true" asyncTimeout="10000" connectionLinger="25" connectionTimeout="60000" name="NIOConnector" pollerThreadPriority="1" port="8888" protocol="org.apache.coyote.http11.Http11NioProtocol" redirectPort="8443" tcpNoDelay="false"/>

Changes in context.xml

<ResourceLink global="jms/broker" name="jms/broker" type="javax.jms.ConnectionFactory"/>
<ResourceLink global="jms/topic/MyTopic" name="jms/topic/MyTopic" type="javax.jms.Topic"/>
<ResourceLink global="jms/queue/MyQueue" name="jms/queue/MyQueue" type="javax.jms.Queue"/>

You can also get these file from attached zip

Then access
http://localhost:8080/manager/text/resources, got three JMS resource i defined 

OK - Listed global resources of all types
jms/topic/MyTopic:org.apache.activemq.command.ActiveMQTopic
jms/queue/MyQueue:org.apache.activemq.command.ActiveMQQueue
jms/broker:org.apache.activemq.ActiveMQConnectionFactory
UserDatabase:org.apache.catalina.users.MemoryUserDatabase

3. Start apache-activemq-5.4.2, create topic APP.JMS.TOPIC, and queque: APP.JMS.QUEUE

4. Put sample files QuoteStreamerApp.war as attached in webapp folder, then it will report errors, but if don't define NIO connector, this error doesn't exist

2011-10-11 15:53:01 org.apache.catalina.startup.HostConfig checkResources
INFO: Undeploying context [/QuoteStreamerApp]
2011-10-11 15:53:11 org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive QuoteStreamerApp.war
2011-10-11 15:53:52 com.ibm.websphere.webmsg.quotestreamer.AppInit init
INFO: DataSimulator successfully created and set and started.
2011-10-11 15:54:01 com.ibm.webmsg.example.StockServlet setProperties
INFO: Configured properties for quote streamer requests.
2011-10-11 15:54:02 com.ibm.webmsg.example.StockServlet registerURL
INFO: Registered the URL for comet requests.
2011-10-11 15:54:02 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:02 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:04 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:04 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
Comment 1 Konstantin Kolinko 2011-10-12 02:57:34 UTC
(In reply to comment #0)
> You can also get these file from attached zip
> 4. Put sample files QuoteStreamerApp.war as attached in webapp folder

1) You forgot to attach the files.

> 
> 2011-10-11 15:53:01 org.apache.catalina.startup.HostConfig checkResources
> INFO: Undeploying context [/QuoteStreamerApp]

2) What happened before the above line?  Undeploying/redeploying the webapp is not mentioned in your reproduction scenario.

It would better to see the full logs. You may attach them to the issue - no need to paste them into the text field.

3) What pages should I access in web browser to reproduce the issue? It is not mentioned. (The logs say that CoyoteAdapter processes a request. What a request that is?)
Comment 2 viola.lu 2011-10-12 03:07:05 UTC
Created attachment 27764 [details]
tomcat configuration

tomcat configuration
Comment 3 viola.lu 2011-10-12 03:18:05 UTC
Hi, Konstantin:

 Errors were generated when tomcat start. I just directly put it before tomcat start, so it failed when start tomcat. You can start tomcat, and then put it in webapp folder to recreate it. 

I already sent you the application in gmail, which is so large to attache here.

I tried to debug it, but failed to get request.

May i can add a println to get request in this tomcat code.

Full log, but i can't get any hints from this log, is there log level option i can change, so ii can get more details?
2011-10-11 15:52:19 org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive QuoteStreamerApp.war
2011-10-11 15:52:20 org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory docs
2011-10-11 15:52:20 org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory examples
2011-10-11 15:52:20 org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory host-manager
2011-10-11 15:52:20 org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory manager
2011-10-11 15:52:20 org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory ROOT
2011-10-11 15:52:20 org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
2011-10-11 15:52:20 org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
2011-10-11 15:52:20 org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-8888"]
2011-10-11 15:52:20 org.apache.catalina.startup.Catalina start
INFO: Server startup in 3328 ms
2011-10-11 15:53:01 org.apache.catalina.startup.HostConfig checkResources
INFO: Undeploying context [/QuoteStreamerApp]
2011-10-11 15:53:11 org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive QuoteStreamerApp.war
2011-10-11 15:53:52 com.ibm.websphere.webmsg.quotestreamer.AppInit init
INFO: DataSimulator successfully created and set and started.
2011-10-11 15:54:01 com.ibm.webmsg.example.StockServlet setProperties
INFO: Configured properties for quote streamer requests.
2011-10-11 15:54:02 com.ibm.webmsg.example.StockServlet registerURL
INFO: Registered the URL for comet requests.
2011-10-11 15:54:02 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:02 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:04 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:04 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:07 org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-bio-8080"]
2011-10-11 15:54:08 org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
2011-10-11 15:54:08 org.apache.coyote.http11.AbstractHttp11Processor process
SEVERE: Error processing request
java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)
2011-10-11 15:54:09 org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-nio-8888"]
2011-10-11 15:54:10 org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service Catalina
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQConnection[ID:IBM-R86F1CF-2194-1318319631890-0:1] Scheduler] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQ Transport: tcp://localhost/127.0.0.1:61616] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [InactivityMonitor ReadCheck] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [InactivityMonitor WriteCheck] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [Timer-0] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQConnection[ID:IBM-R86F1CF-2194-1318319631890-0:2] Scheduler] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQ Transport: tcp://localhost/127.0.0.1:61616] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [Thread-18] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQ Session Task] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.catalina.loader.WebappClassLoader clearReferencesThreads
SEVERE: The web application [/QuoteStreamerApp] appears to have started a thread named [ActiveMQ Session Task] but has failed to stop it. This is very likely to create a memory leak.
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-bio-8080"]
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["ajp-bio-8009"]
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol stop
INFO: Stopping ProtocolHandler ["http-nio-8888"]
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-bio-8080"]
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["ajp-bio-8009"]
2011-10-11 15:54:10 org.apache.coyote.AbstractProtocol destroy
INFO: Destroying ProtocolHandler ["http-nio-8888"]
Comment 4 Konstantin Kolinko 2011-10-12 04:31:05 UTC
> I already sent you the application in gmail, which is so large to attache here.

1) I bet that you do not need all 25 Mb of dojox components of dojotoolkit.

The NPE issue is still reproducible if I delete the dojox folder from the webapp and that shrinks its size significantly.

2) Source code for StockServlet is there - thank you, but sources of its parent class BayeuxServlet is not available.

3) To reproduce the issue, open http://localhost:8888/QuoteStreamerApp/

Just open the page in browser and leave it open.

The page sends a flow of POST requests to
/QuoteStreamerApp/stockServlet HTTP/1.1

4) I am running with the following line added to catalina.properties file:
org.apache.coyote.http11.InternalNioInputBuffer.level = FINE

and it shows that there are problems in BayeuxServlet that it calls setHeader() on a response that has already been recycled.
It is an application error. This is unacceptable and can lead to updating a response that is being delivered to a different client.

Stacktrace in localhost.2011-10-12.log:

12-окт-2011 08:04:02.078 SEVERE [http-nio-8888-exec-8] org.apache.catalina.core.StandardWrapperValve.event Servlet.service() for servlet [StockServlet] in context with path [/QuoteStreamerApp] threw exception
 java.lang.IllegalStateException: The response object has been recycled and is no longer associated with this facade
	at org.apache.catalina.connector.ResponseFacade.isCommitted(ResponseFacade.java:325)
	at org.apache.catalina.connector.ResponseFacade.setHeader(ResponseFacade.java:518)
	at com.ibm.ws.webmsg.servlet.adapter.ServletResponse.setHeader(ServletResponse.java:147)
	at com.ibm.ws.webmsg.client.bayeux.protocol.vone.JSONTransport.endResponse(JSONTransport.java:191)
	at com.ibm.ws.webmsg.client.bayeux.protocol.vone.processor.EventDeliveryProcessor.close(EventDeliveryProcessor.java:139)
	at com.ibm.ws.webmsg.client.bayeux.protocol.vone.WASCEClientImpl.shutdown(WASCEClientImpl.java:117)
	at com.ibm.ws.webmsg.client.bayeux.protocol.vone.processor.DisconnectProcessor.processMessage(DisconnectProcessor.java:63)
	at com.ibm.ws.webmsg.client.bayeux.protocol.vone.ClientImpl.processRequest(ClientImpl.java:332)
	at com.ibm.webmsg.servlet.BayeuxServlet.handleRead(BayeuxServlet.java:233)
	at com.ibm.webmsg.servlet.BayeuxServlet.event(BayeuxServlet.java:210)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilterEvent(ApplicationFilterChain.java:482)
	at org.apache.catalina.core.ApplicationFilterChain.doFilterEvent(ApplicationFilterChain.java:376)
	at org.apache.catalina.core.StandardWrapperValve.event(StandardWrapperValve.java:414)
	at org.apache.catalina.core.StandardContextValve.event(StandardContextValve.java:192)
	at org.apache.catalina.valves.ValveBase.event(ValveBase.java:226)
	at org.apache.catalina.core.StandardHostValve.event(StandardHostValve.java:245)
	at org.apache.catalina.valves.ValveBase.event(ValveBase.java:226)
	at org.apache.catalina.valves.ValveBase.event(ValveBase.java:226)
	at org.apache.catalina.core.StandardEngineValve.event(StandardEngineValve.java:138)
	at org.apache.catalina.connector.CoyoteAdapter.event(CoyoteAdapter.java:211)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:411)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:970)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:515)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550)
	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)


5) There are a lot of exceptions like
javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616. Reason: java.net.ConnectException: Connection refused: connect

but the NullPointerException at CoyoteAdapter.java:436 is reproducible.

6) The NPE is reproducible both in 7.0.22 and in trunk.


The requests to of them fail with error 500, but response sizes in different requests are different.

I noted the following while debugging trunk:

1. In access log all requests are POST to /QuoteStreamerApp/stockServlet.
They all fail with error 500, but response sizes are different.

2. After the call to getPipeline().getFirst().invoke(request, response) the value of request.isComet() is true.

3. The cause for NPE at CoyoteAdapter.java:436 is that at that point the request is already recycled and request.getMappingData().context  is null.

4. The recycling happens in the finally block in CoyoteAdapter#event(..),
lines 252-254:
            if (error || response.isClosed() || !request.isComet()) {
                request.recycle();
                request.setFilterChain(null);
                response.recycle();
            }

I do not know much about request that is being recycled. It is not the first request that was received.

5. If I put breakpoint on the request.recycle() call above, the call stack is:

CoyoteAdapter.event(Request, Response, SocketStatus) line: 252	
CoyoteAdapter.service(Request, Response) line: 411	
Http11NioProcessor(AbstractHttp11Processor<S>).process(SocketWrapper<S>) line: 970	
Http11NioProtocol$Http11ConnectionHandler(AbstractProtocol$AbstractConnectionHandler<S,P>).process(SocketWrapper<S>, SocketStatus) line: 515	
NioEndpoint$SocketProcessor.run() line: 1550	

After returning from event() call on CoyoteAdapter:411 (the call returns false) the lines 431..440 are executed:
            } else if (!comet) {
                request.finishRequest();
                response.finishResponse();
                if (postParseSuccess) {
                    // Log only if processing was invoked.
                    // If postParseRequest() failed, it has already logged it.
                    ((Context) request.getMappingData().context).logAccess(
                            request, response,
                            System.currentTimeMillis() - req.getStartTime(),
                            false);
                }

The comet variable is false and postParseSuccess is true.
The request is already recycled and request.getMappingData().context is null, leading to an NPE.
Comment 5 viola.lu 2011-10-12 13:01:40 UTC
You should start an activemq server, then javax.jms.JMSException will be gone.

I already sent you source of project, pls check your gmail.

Thanks in advance!
Comment 6 Konstantin Kolinko 2011-10-13 07:11:46 UTC
(In reply to comment #4)
> 4) I am running with the following line added to catalina.properties file:
> org.apache.coyote.http11.InternalNioInputBuffer.level = FINE

Ops. I meant the following line:
org.apache.catalina.connector.RECYCLE_FACADES=true

> 
> and it shows that there are problems in BayeuxServlet that it calls setHeader()
> on a response that has already been recycled. (...)
Comment 7 Mark Thomas 2011-10-14 11:11:54 UTC
Adding users to the cc list without their explicit permission is extremely rude. You MUST NOT do this. Repeated abuse of Bugzilla in this or any other way will result in your access to Bugzilla being blocked.

All changes to any Bugzilla issues is automatically routed to the appropriate dev list where all the Apache committers for a project will see it.
Comment 8 Mark Thomas 2011-10-14 12:58:03 UTC
(In reply to comment #4)
> 4) I am running with the following line added to catalina.properties file:
> org.apache.catalina.connector.RECYCLE_FACADES=true
> 
> and it shows that there are problems in BayeuxServlet that it calls setHeader()
> on a response that has already been recycled.
> It is an application error. This is unacceptable and can lead to updating a
> response that is being delivered to a different client.

Yep. That makes this an application / Bayeux library error rather than a Tomcat bug.
Comment 9 Konstantin Kolinko 2011-10-14 13:05:10 UTC
(In reply to comment #8)
> (In reply to comment #4)
> > 4) I am running with the following line added to catalina.properties file:
> > org.apache.catalina.connector.RECYCLE_FACADES=true
> Yep. That makes this an application / Bayeux library error rather than a Tomcat
> bug.

See in comment #4:
> 6) The NPE is reproducible both in 7.0.22 and in trunk.
> (..) 
> 
> 3. The cause for NPE at CoyoteAdapter.java:436 is that at that point the
> request is already recycled and request.getMappingData().context  is null.
> 
> 4. The recycling happens in the finally block in CoyoteAdapter#event(..),
> lines 252-254:
>             if (error || response.isClosed() || !request.isComet()) {
>                 request.recycle();
>                 request.setFilterChain(null);
>                 response.recycle();
>             }
> 
> I do not know much about request that is being recycled. It is not the first
> request that was received.
> 
> 5. If I put breakpoint on the request.recycle() call above, the call stack is:
> 
> CoyoteAdapter.event(Request, Response, SocketStatus) line: 252    
> CoyoteAdapter.service(Request, Response) line: 411    
> Http11NioProcessor(AbstractHttp11Processor<S>).process(SocketWrapper<S>) line:
> 970    
> Http11NioProtocol$Http11ConnectionHandler(AbstractProtocol$AbstractConnectionHandler<S,P>).process(SocketWrapper<S>,
> SocketStatus) line: 515    
> NioEndpoint$SocketProcessor.run() line: 1550    
> 
> After returning from event() call on CoyoteAdapter:411 (the call returns false)
> the lines 431..440 are executed:
>             } else if (!comet) {
>                 request.finishRequest();
>                 response.finishResponse();
>                 if (postParseSuccess) {
>                     // Log only if processing was invoked.
>                     // If postParseRequest() failed, it has already logged it.
>                     ((Context) request.getMappingData().context).logAccess(
>                             request, response,
>                             System.currentTimeMillis() - req.getStartTime(),
>                             false);
>                 }
> 
> The comet variable is false and postParseSuccess is true.
> The request is already recycled and request.getMappingData().context is null,
> leading to an NPE.

The above is a legitimate bug. Recycling in event() -> returning to service() -> NPE when trying to log it.
Comment 10 viola.lu 2011-10-14 13:25:24 UTC
Hi, Mark:

 Sorry to add you to the cc list without notification in advance. I tried to send email to markt@apache.org, but rejected, and you are the NIO connector code owner, so i did it. Thanks for your understanding.

 This application can work on tomcat 6.0.19, but failed in trunk and 7.0.9/22, so i think it's tomcat nio connector problem. If i don't add NIO connector to server.xml, there is no exception.
Comment 11 Mark Thomas 2011-10-14 15:03:08 UTC
(In reply to comment #9)
> > 5. If I put breakpoint on the request.recycle() call above, the call stack is:
> > 
> > CoyoteAdapter.event(Request, Response, SocketStatus) line: 252    
> > CoyoteAdapter.service(Request, Response) line: 411    
> > Http11NioProcessor(AbstractHttp11Processor<S>).process(SocketWrapper<S>) line:
> > 970    
> > Http11NioProtocol$Http11ConnectionHandler(AbstractProtocol$AbstractConnectionHandler<S,P>).process(SocketWrapper<S>,
> > SocketStatus) line: 515    
> > NioEndpoint$SocketProcessor.run() line: 1550    
> > 
> > After returning from event() call on CoyoteAdapter:411 (the call returns false)
> > the lines 431..440 are executed:
> >             } else if (!comet) {
> >                 request.finishRequest();
> >                 response.finishResponse();
> >                 if (postParseSuccess) {
> >                     // Log only if processing was invoked.
> >                     // If postParseRequest() failed, it has already logged it.
> >                     ((Context) request.getMappingData().context).logAccess(
> >                             request, response,
> >                             System.currentTimeMillis() - req.getStartTime(),
> >                             false);
> >                 }
> > 
> > The comet variable is false and postParseSuccess is true.
> > The request is already recycled and request.getMappingData().context is null,
> > leading to an NPE.
> 
> The above is a legitimate bug. Recycling in event() -> returning to service()
> -> NPE when trying to log it.

Sorry. Missed that. I'll take a look.

(In reply to comment #10)
> Hi, Mark:
> 
> Sorry to add you to the cc list without notification in advance. I tried to
> send email to markt@apache.org, but rejected, and you are the NIO connector
> code owner, so i did it. Thanks for your understanding.

1. I am not the maintainer of the NIO code. All of the committers work on all of the code base. There are no project or component leads at the ASF.

2. Sending private mails to individual committers is also frowned upon and most committers (me included) reject or ignore them. The only place to discuss change to the Tomcat code base is the dev@tomcat.a.o mailing list.

>  This application can work on tomcat 6.0.19, but failed in trunk and 7.0.9/22,
> so i think it's tomcat nio connector problem. If i don't add NIO connector to
> server.xml, there is no exception.

See above.
Comment 12 Mark Thomas 2011-10-14 20:59:48 UTC
The NPE has been fixed in trunk and 7.0.x and will be included in 7.0.23 onwards.
Comment 13 viola.lu 2011-10-17 03:35:53 UTC
Thanks for your quick response. I run the test app against, no exception now. Thanks again.
If i offended you , pls forgive. THanks.