Bug 52009

(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?)

Created attachment 27764 [details]
tomcat configuration

tomcat configuration

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"]

> 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.

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!

(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. (...)

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.

(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.

(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.

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.

(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.

The NPE has been fixed in trunk and 7.0.x and will be included in 7.0.23 onwards.

Thanks for your quick response. I run the test app against, no exception now. Thanks again.
If i offended you , pls forgive. THanks.

I think this issue is reintroduced in tomcat 7.0.68.
I see in http://svn.apache.org/repos/asf/tomcat/tc7.0.x/tags/TOMCAT_7_0_67/java/org/apache/catalina/connector/CoyoteAdapter.java:
{code}
if (postParseSuccess &&
                        request.getMappingData().context != null) {
                    // Log only if processing was invoked.
                    // If postParseRequest() failed, it has already logged it.
                    // If context is null this was the start of a comet request
                    // that failed and has already been logged.
                    ((Context) request.getMappingData().context).logAccess(
{code}
While in http://svn.apache.org/repos/asf/tomcat/tc7.0.x/tags/TOMCAT_7_0_68/java/org/apache/catalina/connector/CoyoteAdapter.java:
{code}
   if (postParseSuccess) {
                        // Log only if processing was invoked.
                        // If postParseRequest() failed, it has already logged it.
                        // If context is null this was the start of a comet request
                        // that failed and has already been logged.
                        ((Context) request.getMappingData().context).logAccess(
{code}
I can not find out where this has been changed from svn logs :-(
Do you want me to log a new ticket for this?

http://svn.apache.org/viewvc?view=revision&revision=1720757

This bug is fixed. If you are experiencing a similar bug then please open a new issue and provide the steps to reproduce it from a clean Tomcat install.