Bug 58646 - NullPointerException in InternalNioOutputBuffer
Summary: NullPointerException in InternalNioOutputBuffer
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.28
Hardware: PC Linux
: P3 normal (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-11-24 21:39 UTC by Alexander Malyshev
Modified: 2018-07-20 20:12 UTC (History)
0 users


Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Alexander Malyshev 2015-11-24 21:39:08 UTC 
We're using Tomcat in our product. Under traffic we can reproduce the following exceptions:

Nov 23, 2015 CST 08:34:58.115 PM org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.

Nov 23, 2015 CST 08:34:58.118 PM org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response

java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:234)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:189)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:177)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:741)
	at org.apache.coyote.Response.action(Response.java:177)
	at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
	at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1804)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1143)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


We have several applications deployed on our Tomcat. Most of the applications are simple Jersey Rest service applications. Above NullPointer is related to one of them (basically, the one which is called during traffic - I bet other apps will have the same issue if they would be called). Also we have one application which is using WebSockets (Tomcat implementation) and Async support for Comet. WebSocket interface is used during traffic testing while Comet is NOT (Servlets are not called). We have the following in our Tomcat main web.xml file (comparing to the default one):


    <filter>
        <filter-name>CorsFilter</filter-name>
        <filter-class>com.avaya.acc.base.web.filters.CorsFilter</filter-class>
        <async-supported>true</async-supported>
    </filter>
    <filter-mapping>
        <filter-name>CorsFilter</filter-name>
        <url-pattern>/*</url-pattern>
    </filter-mapping>

    <filter>
        <filter-name>NoCachingFilter</filter-name>
        <filter-class>com.avaya.acc.base.web.filters.NoCachingFilter</filter-class>
        <async-supported>true</async-supported>
        <init-param>
          <param-name>Set-Expires</param-name>
          <param-value>false</param-value>
        </init-param>
        <init-param>
          <param-name>No-Store</param-name>
          <param-value>true</param-value>
        </init-param>
    </filter>
    <filter-mapping>
        <filter-name>NoCachingFilter</filter-name>
        <url-pattern>/*</url-pattern>
    </filter-mapping>
    
    <!-- enable caching for static content -->
    <context-param>
        <param-name>NoCachingFilter enableCaching</param-name>
        <param-value>Set-Expires=true;No-Store=false;patterns=*.js,*.swf,*.jar,*.png,*.jpg,*.css</param-value>
    </context-param>
    
    <!-- Declaring this param in web.xml for specific webapp doesn't work, so leaving it here -->
    <context-param>
        <param-name>stinger.excluded.url.patterns</param-name>
        <param-value>/Comet/StartLiveSession,/Comet/Data,/Comet/EndLiveSession</param-value>
    </context-param>
 
And the following in the web.xml for application which has issues:

<?xml version="1.0" encoding="UTF-8"?>

<web-app version="2.5" xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd">
    <servlet>
        <servlet-name>Live Viewer</servlet-name>
        <servlet-class>org.glassfish.jersey.servlet.ServletContainer</servlet-class>

        <init-param>
                <param-name>javax.ws.rs.Application</param-name>
                <param-value>com.avaya.acc.wcs.api.viewer.rest.app.LiveViewerRestApp</param-value>
        </init-param>

        <init-param>
            <!-- integrates JERSEY and JACKSON -->
            <param-name>com.sun.jersey.api.json.POJOMappingFeature</param-name>
            <param-value>true</param-value>
        </init-param>
        <init-param>
            <param-name>sendfileSize</param-name>
            <param-value>-1</param-value>
        </init-param>
        <load-on-startup>1</load-on-startup>
    </servlet>

    <servlet-mapping>
        <servlet-name>Live Viewer</servlet-name>
        <url-pattern>/rest/*</url-pattern>
    </servlet-mapping>
</web-app>

I tried to remove async-supported from all our web.xml files and the issue is gone. So it's definitely related to <async-supported> configuration - without even actually using async functionality. We still need async-supported for our Comet interface so just disabling async is not an option for us.

I can turn on some additional logging and reproduce again if this will help - just let me know which logging is needed.
Comment 1 Alexander Malyshev 2015-11-24 22:26:59 UTC 
After some more testing it turns out it's not related to async-supported tag. It's just intermittent. Also, sometimes this one happens before below exceptions:

Nov 24, 2015 CST 04:18:48.480 PM org.apache.catalina.connector.CoyoteAdapter
INFO: Encountered a non-recycled request and recycled it forcedly.

org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException
	at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:710)
	at org.apache.coyote.http11.AbstractHttp11Processor.recycle(AbstractHttp11Processor.java:1828)
	at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:219)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:727)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Comment 2 Alexander Malyshev 2015-11-24 22:37:06 UTC 
Note also that the amount of regular HTTP request during testing is not huge - nearly 10-12 requests/second. Amount of websocket traffic is huge, but it does not seem to affect these exceptions - issue can happen in the beginning of the test when WS traffic is still small as well as in the end of the test.
Comment 3 Konstantin Kolinko 2015-11-24 22:53:53 UTC 
1)
> Nov 23, 2015 CST 08:34:58.115 PM org.apache.coyote.http11.Http11NioProcessor
> INFO: Error parsing HTTP request header
> Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.

The above logging is controlled by org.apache.juli.logging.UserDataHelper.CONFIG system property [1].

The log message was likely written by "catch (Throwable t)" clause in AbstractHttp11Processor.process(). That is the only place where UserDataHelper is used in a processor.

Unfortunately, it does not log the stacktrace, even with debug logging. It can be improved with a code change in AbstractHttp11Processor.java line 1058,

-                            getLog().debug(message);
+                            getLog().debug(message, t);

(An easy test case: I have seen such messages when erroneously trying to connect with https:// to a http connector.)


2)
I do not see thread names in your log. It is likely that the two errors are related (being just 3ms apart), but it is unclear whether the two errors occurred in the same thread.

It is known that org.apache.juli.OneLineFormatter writes the thread names.


3) Usual advice with misbehaving requests/responses is to add the following property into conf/catalina.properties file:  [2]

org.apache.catalina.connector.RECYCLE_FACADES=true

It should make your configuration more robust against common mistake of accessing Request/Response objects outside of their life cycle.


4) BTW, Tomcat 8.0.29 was released several hours ago. I think that it will be announced tomorrow.


[1] http://tomcat.apache.org/tomcat-8.0-doc/config/systemprops.html#Logging
[2] http://tomcat.apache.org/tomcat-8.0-doc/security-howto.html#System_Properties
Comment 4 Mark Thomas 2015-11-25 14:10:20 UTC 
Correct title based on additional information.
Comment 5 Mark Thomas 2015-11-25 14:19:12 UTC 
I've added the stack trace to the log message.

Initial impressions of this issue are an application bug along the lines of retaining a reference to the response.
Comment 6 Alexander Malyshev 2015-11-25 18:01:34 UTC 
I don't think it's application bug. During traffic testing only the following requests are sent:

1) Requests to get static content. Fully processed by tomcat - only filters apply.
2) Request to get one Jersey REST service which is really simple and is not using request or response directly.
3) WebSocket requests processed by Tomcat WS implementation.

The only custom part here are filters, but they are pretty simple and I can disable them and run test again. Also, they're not remembering request or response objects - only get and use them inside doFilter() method.

Note though that setting org.apache.catalina.connector.RECYCLE_FACADES=true seem to fix an issue (I can't be sure as before issue was intermittent as well). But at least I had a few traffic runs without this issue.
Comment 7 Alexander Malyshev 2015-11-26 01:00:55 UTC 
Ok, It seems like the issue happens even with org.apache.catalina.connector.RECYCLE_FACADES=true.

Following are the exceptions I got:

Nov 25, 2015 CST 06:10:52.115 PM http-nio-135.60.87.69-443-exec-4 org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.

---- 500 milliseconds between these 2 -------

Nov 25, 2015 CST 06:10:52.697 PM http-nio-135.60.87.69-443-exec-5 org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[jsp]
SEVERE: Servlet.service() for servlet [jsp] in context with path [] threw exception [java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade] with root cause

java.lang.IllegalStateException: The request object has been recycled and is no longer associated with this facade
	at org.apache.catalina.connector.RequestFacade.getMethod(RequestFacade.java:743)
	at org.apache.jsp.index_jsp._jspService(index_jsp.java:82)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:438)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:396)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:340)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.avaya.acc.base.web.filters.NoCachingFilter.doFilter(NoCachingFilter.java:106)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at com.avaya.acc.base.web.filters.CorsFilter.handleSimpleCORS(CorsFilter.java:438)
	at com.avaya.acc.base.web.filters.CorsFilter.doFilter(CorsFilter.java:289)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
	at com.avaya.acc.base.web.valves.StingerValve.invoke(StingerValve.java:150)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
	at com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:290)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


Nov 25, 2015 CST 06:10:52.703 PM http-nio-135.60.87.69-443-exec-7 org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[jsp]
SEVERE: Servlet.service() for servlet [jsp] in context with path [] threw exception

java.lang.NullPointerException
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
	at com.avaya.acc.base.web.valves.StingerValve.invoke(StingerValve.java:150)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
	at com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:290)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


Nov 25, 2015 CST 06:10:52.704 PM http-nio-135.60.87.69-443-exec-7 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error processing request

java.lang.NullPointerException
	at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1500)
	at org.apache.catalina.connector.Request.setAttribute(Request.java:1490)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:159)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
	at com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:290)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


Nov 25, 2015 CST 06:10:52.705 PM http-nio-135.60.87.69-443-exec-7 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response

java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:234)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:189)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:177)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:741)
	at org.apache.coyote.Response.action(Response.java:177)
	at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
	at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1804)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1143)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

Note that 3 different threads are involved.

I'll collect access logs and enable org.apache.juli.logging.UserDataHelper.CONFIG=INFO next time.
Comment 8 Mark Thomas 2015-11-30 09:50:41 UTC 
(In reply to Alexander Malyshev from comment #6)
> I don't think it's application bug.

All the evidence so far points to an application bug being more likely than a Tomcat bug.

> The only custom part here are filters,

That statement is not correct as a quick look at the stack traces shows:
com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve
com.avaya.acc.base.web.valves.StingerValve

> Note though that setting org.apache.catalina.connector.RECYCLE_FACADES=true
> seem to fix an issue

It won't fix the issue, it will just make it more obvious where the problem lies by triggering NPEs.
Comment 9 Alexander Malyshev 2015-11-30 20:16:32 UTC 
Well, I don't see how NullPointer in Tomcat code can possibly be an application bug.

I forgot about these two valves, but, again, they never store request/response objects so they definitely are not using these objects outside of invoke method - and it's legal to use them inside of this method.

I added some additional logging (as well as upgraded to 8.0.29) and now waiting to reproduce it again. As usually - once I enabled logging it's gone :) 

I always saw this one:

Nov 23, 2015 CST 08:34:58.115 PM org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.

before all the null pointers so I'm 99% sure these are related. Let me get a stack trace of this one as well as additional logging and we'll see what's happening.
Comment 10 Christopher Schultz 2015-11-30 23:29:26 UTC 
(In reply to Alexander Malyshev from comment #9)
> Well, I don't see how NullPointer in Tomcat code can possibly be an
> application bug.

package com.your.code;

public class BrokeFilter implements Filter {
  public void toFilter(ServletRequest request, ServletResponse response, FilterChain chain) {
    chain.doFilter(null, null);
  }
}

Tomcat is going to throw an NPE somewhere down the line, yet the bug is in application code.

Yes, Tomcat could protect against this kind of thing, but adding thousands of null-checks to things that obviously shouldn't be null isn't a good use of time in a high-performance server.
Comment 11 Mark Thomas 2015-12-14 21:38:05 UTC 
There isn't enough information here (yet) to demonstrate a Tomcat bug or reproduce the issue.
Comment 12 Alexander Malyshev 2015-12-15 04:53:50 UTC 
Yes, I agree. For some reason I can easily reproduce it with clean tomcat 8.0.29, but once I add logging to it to investigate further - it disappears..
I'll be running more traffic during this week so, hopefully, I'll be able to catch it.
Comment 13 Julie 2016-01-07 18:22:02 UTC 
(In reply to Alexander Malyshev from comment #12)
> Yes, I agree. For some reason I can easily reproduce it with clean tomcat
> 8.0.29, but once I add logging to it to investigate further - it disappears..
> I'll be running more traffic during this week so, hopefully, I'll be able to
> catch it.

Were you able to reproduce the issue with traffic ?
Comment 14 Julie 2016-01-07 18:24:48 UTC 
I am seeing similar errors in my log under traffic. I am using tomcat 8.0.15
Comment 15 Alexander Malyshev 2016-01-15 14:26:45 UTC 
Ok, finally I was able to reproduce it with logs.
I associated ID with each request object and I added logging to AbstractHttp11Processor  class to process() and recycle() methods.

In process() method I added the following log in the very beginning:

    getLog().info("Starting to process request with id " + this.request.id + ". Calling method is:\n" + java.lang.Thread.currentThread().getStackTrace()[3]);

and the following log later then request path is parsed (copying a few above lines as well to make it clean):

        if ((!getInputBuffer().parseRequestLine(this.keptAlive)) && 
          (handleIncompleteRequestLineRead()))
        {
          break;
        }

        getLog().info("Processing " + this.request.method() + " request to " + this.request.requestURI() + ".");

In the recycle() method I added log in the very beginning:

getLog().info("Recycling processor with id " + this.request.id + ". Calling method is:\n" + java.lang.Thread.currentThread().getStackTrace()[2]);
    
What I got is that 2 different Tomcat threads started to process the same request (logs are ordered properly):

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23 org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23 org.apache.coyote.http11.Http11NioProcessor
INFO: Processing POST request to /viewer/rest/live_viewer/.

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17 org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17 org.apache.coyote.http11.Http11NioProcessor
INFO: Processing POST request to /viewer/rest/live_viewer/.

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-17 org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.

java.lang.IllegalStateException: Unexpected state: headers already parsed. Buffer not recycled?
	at org.apache.coyote.http11.AbstractNioInputBuffer.parseHeaders(AbstractNioInputBuffer.java:375)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1029)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

Jan 15, 2016 MSK 04:52:13.914 PM http-nio-135.60.87.68-443-exec-23 com.avaya.acc.wcs.logic.api.GetPresentationTocCommand
INFO: Processing LIVE_VIEWER event for client with Participant ID null


Last log is aour app log and means that http-nio-135.60.87.68-443-exec-23 thread processed request successfully.
I think there is a synchronization issue somethere in tomcat code which makes it possible for 2 threads to process the same request object simultaneously.

Here is another exception - but the reason seem to be the same:

Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-16 org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)

Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-16 org.apache.coyote.http11.Http11NioProcessor
INFO: Processing GET request to /wcsws/WebSocket.

Jan 15, 2016 MSK 04:52:14.028 PM http-nio-135.60.87.68-443-exec-1 org.apache.coyote.http11.Http11NioProcessor
INFO: Starting to process request with id 13. Calling method is:
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)

Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-1 org.apache.coyote.http11.Http11NioProcessor
INFO: Processing GET request to /wcsws/WebSocket.

Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-1 org.apache.coyote.http11.Http11NioProcessor
INFO: Recycling processor with id 13. Calling method is:
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:218)

Jan 15, 2016 MSK 04:52:14.029 PM http-nio-135.60.87.68-443-exec-16 org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/wcsws].[default]
SEVERE: Servlet.service() for servlet [default] in context with path [/wcsws] threw exception

java.lang.NullPointerException
	at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1505)
	at org.apache.catalina.connector.Request.access$000(Request.java:118)
	at org.apache.catalina.connector.Request$3.set(Request.java:3380)
	at org.apache.catalina.connector.Request.setAttribute(Request.java:1462)
	at org.apache.catalina.connector.RequestFacade.setAttribute(RequestFacade.java:539)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:272)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
	at com.avaya.acc.base.web.valves.StingerValve.invoke(StingerValve.java:150)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
	at com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:269)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

Jan 15, 2016 MSK 04:52:14.040 PM http-nio-135.60.87.68-443-exec-16 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error processing request

java.lang.NullPointerException
	at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1505)
	at org.apache.catalina.connector.Request.setAttribute(Request.java:1495)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:158)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
	at com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve.invoke(MCPTomcatAccessLogValve.java:269)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

Jan 15, 2016 MSK 04:52:14.040 PM http-nio-135.60.87.68-443-exec-16 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response

java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:236)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:191)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:179)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:741)
	at org.apache.coyote.Response.action(Response.java:177)
	at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
	at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1813)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1152)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Comment 16 Alexander Malyshev 2016-01-18 12:07:16 UTC 
I can add more logs and reproduce again - just let me know the place to add logs.
Comment 17 Mark Thomas 2016-01-18 16:59:03 UTC 
Thanks for the additional information. It is certainly more information of the right type but it isn't (yet) enough to figure out what is going on.

I think whatever is going wrong, has already gone wrong by the time the log messages provided in comment #15 are reached. What might provide further insight is including the log messages for at least one whole (correctly processed) request prior to the point where things went wrong for each of the threads involved and the processor involved.

In terms of what might be going wrong, one possibility is that a Processor is getting added more than once to the recycled processor pool. I can'tsee how that might happen but adding logging in AbstractProtocol.RecycledProcessors.push() inside the if (offer) { ... } block might provide an idea of if something is going wrong there.
Comment 18 Iztok 2016-01-27 12:12:49 UTC 
I have a very similar situation (on Tomcat 7.0.65) that happens after several hours of service:

gen 12, 2016 7:03:19 PM org.apache.coyote.http11.AbstractHttp11Processor process
Informazioni: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.
java.lang.NumberFormatException: null
        at java.lang.Integer.parseInt(Integer.java:454)
        at java.lang.Integer.parseInt(Integer.java:527)
        at org.myapp.web.servlet.StreamingServlet.doStreaming(StreamingServlet.java:138)
        at org.myapp.web.servlet.StreamingServlet.service(StreamingServlet.java:43)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.myapp.web.filter.LogRequestFilter.doFilter(LogRequestFilter.java:117)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)
gen 12, 2016 7:03:19 PM org.apache.catalina.connector.CoyoteAdapter checkRecycled
Informazioni: Encountered a non-recycled response and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException
        at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:592)
        at org.apache.coyote.http11.AbstractHttp11Processor.recycle(AbstractHttp11Processor.java:1813)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:218)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:708)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)

gen 12, 2016 7:03:27 PM org.apache.coyote.http11.AbstractHttp11Processor process
Informazioni: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.
java.lang.NumberFormatException: null
        at java.lang.Integer.parseInt(Integer.java:454)
        at java.lang.Integer.parseInt(Integer.java:527)
        at org.myapp.web.servlet.StreamingServlet.doStreaming(StreamingServlet.java:138)
        at org.myapp.web.servlet.StreamingServlet.service(StreamingServlet.java:43)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.myapp.web.filter.LogRequestFilter.doFilter(LogRequestFilter.java:117)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)
		
gen 12, 2016 7:03:27 PM org.apache.catalina.connector.CoyoteAdapter checkRecycled
Informazioni: Encountered a non-recycled response and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException
        at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:592)
        at org.apache.coyote.http11.AbstractHttp11Processor.recycle(AbstractHttp11Processor.java:1813)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:218)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:708)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)

        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)
gen 12, 2016 7:03:27 PM org.apache.coyote.http11.AbstractHttp11Processor process
Grave: Error processing request
java.lang.NullPointerException
        at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:233)
        at org.apache.coyote.http11.InternalNioOutputBuffer.endRequest(InternalNioOutputBuffer.java:121)
        at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:762)
        at org.apache.coyote.Response.action(Response.java:174)
        at org.apache.coyote.Response.finish(Response.java:274)
        at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:319)
        at org.apache.catalina.connector.Response.finishResponse(Response.java:553)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:450)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)

gen 12, 2016 7:03:27 PM org.apache.coyote.http11.AbstractHttp11Processor endRequest
Grave: Error finishing response
java.lang.NullPointerException
        at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:233)
        at org.apache.coyote.http11.InternalNioOutputBuffer.endRequest(InternalNioOutputBuffer.java:121)
        at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1788)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1131)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)

gen 12, 2016 7:03:33 PM org.apache.catalina.connector.CoyoteAdapter checkRecycled
Informazioni: Encountered a non-recycled response and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException
        at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:592)
        at org.apache.coyote.http11.AbstractHttp11Processor.recycle(AbstractHttp11Processor.java:1813)
        at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:218)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:708)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1757)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1716)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)



Below you can see the localhost_access_log. Pay attention on lines with date '01/Jan/1970:00:59:59'. The request has no method, no URL, but Tomcat still return code 200 and no bytes. In other cases returns 500.
		
		
		
10.121.210.247 user1 [12/Jan/2016:19:03:19 +0100] "GET /streaming?id=147366 HTTP/1.1" 400 0 8206
- - [01/Jan/1970:00:59:59 +0100] "-" 200 0 -
10.121.210.247 user2 [12/Jan/2016:19:03:19 +0100] "GET /streaming?id=145255 HTTP/1.1" 200 149 24605
10.120.56.102 user1 [12/Jan/2016:19:03:22 +0100] "GET /streaming?id=147366 HTTP/1.1" 200 233 24605
10.121.210.247 user2 [12/Jan/2016:19:03:22 +0100] "GET /streaming?id=145255 HTTP/1.1" 200 155 24605
10.120.56.102 user1 [12/Jan/2016:19:03:26 +0100] "GET /streaming?id=147366 HTTP/1.1" 200 244 24605
10.121.210.247 user2 [12/Jan/2016:19:03:27 +0100] "GET /streaming?id=145258 HTTP/1.1" 400 0 8206
10.121.210.247 - [01/Jan/1970:00:59:59 +0100] "-" 200 0 8194
- - [01/Jan/1970:00:59:59 +0100] "-" 500 0 -
10.121.210.247 user2 [12/Jan/2016:19:03:28 +0100] "GET /streaming?id=145258 HTTP/1.1" 200 153 24605
10.121.210.247 user2 [12/Jan/2016:19:03:30 +0100] "GET /streaming?id=145258 HTTP/1.1" 200 153 24605
10.120.56.102 user1 [12/Jan/2016:19:03:31 +0100] "GET /streaming?id=147366 HTTP/1.1" 200 214 24605
10.120.56.102 user1 [12/Jan/2016:19:03:33 +0100] "GET /streaming?id=147366 HTTP/1.1" 200 255 24605
10.121.210.247 user2 [12/Jan/2016:19:03:33 +0100] "GET /streaming?id=145258 HTTP/1.1" 400 0 16406
10.121.210.247 - [01/Jan/1970:00:59:59 +0100] "-" 200 0 -
10.120.56.102 user1 [12/Jan/2016:19:03:34 +0100] "GET /streaming?id=147366 HTTP/1.1" 200 266 24605
Comment 19 Mark Thomas 2016-02-01 08:42:24 UTC 
Steps to reproduce still required.
Comment 20 miro-ch 2016-02-04 13:47:57 UTC 
Hi everybody, we have exactly the same problem. We get every few hours "Error parsing HTTP request header" and then we must restart tomcat. Does anyone have a solution for this problem? Thanks.
Comment 21 Alexander Malyshev 2016-02-15 15:16:33 UTC 
Ok, I added some additional logs and here is what we have:

Feb 15, 2016 MSK 05:34:24.157 PM http-nio-135.60.87.68-443-exec-34 org.apache.coyote.http11.Http11NioProtocol
INFO: Starting to process processor with request 500. Procassor source: connections map.Calling method is:
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:634)

Feb 15, 2016 MSK 05:34:24.157 PM http-nio-135.60.87.68-443-exec-34 org.apache.coyote.http11.Http11NioProcessor
INFO: Processing GET request to /viewer/wcc/app.swf.

Feb 15, 2016 MSK 05:34:24.157 PM http-nio-135.60.87.68-443-exec-34 com.avaya.acc.base.tomcat.MCPTomcatAccessLogValve
INFO: 135.60.87.91 - - [15/Feb/2016:17:34:23 +0300] "GET /viewer/wcc/app.swf HTTP/1.1" 200 -

...

Feb 15, 2016 MSK 05:34:24.170 PM http-nio-135.60.87.68-443-exec-34 org.apache.coyote.AbstractProtocol$RecycledProcessors
INFO: Pushing processor with request 500 to RecycledProcessors. Calling method is:
org.apache.coyote.AbstractProtocol$RecycledProcessors.push(AbstractProtocol.java:906)

Feb 15, 2016 MSK 05:34:24.170 PM http-nio-135.60.87.68-443-exec-34 org.apache.coyote.AbstractProtocol$RecycledProcessors
INFO: Pushing processor with request 500 to RecycledProcessors. Calling method is:
org.apache.coyote.AbstractProtocol$RecycledProcessors.push(AbstractProtocol.java:906)

As you can see, thread just processes standard static content request and after request is processed it pushes processor 2 times to the RecycledProcessors map..

Note that I have incorrect calling method log in last two lines, so it's hard to say which exact places into AbstractProtocol.AbstractConnectionHandler.process() was called (it has 5 occurences of release() method call, which puts processor back to RecycledProcessors map). In case of upgrade request processing it's theoretically possible (first call in "if (state == SocketState.UPGRADING) {...}" block and second in the end of process() method if IOExcepton is thrown after release is called first time). But, having in mind I've not used websocket at all during this test, I'm not sure how it could call release twise.

I'll correct last log and try to reproduce again.
Comment 22 Alexander Malyshev 2016-02-15 15:48:45 UTC 
Oops.

Some incorrect info in last comment. It turns out I used both comet(implemented using async servlets) and websocket. So call path with "if (state == SocketState.UPGRADING) {...}" and subsequent IOException is possible. Will try to reproduce it.
Comment 23 Mark Thomas 2016-02-15 21:25:36 UTC 
Something to try (that would address the Upgrade + IOE issue above and any similar issues) is to add this:
connections.remove(socket.getSocket());

to the start of:
Http11NioProtocol.Http11ConnectionHandler.release(SocketWrapper,Processor,boolean,boolean)
Comment 24 Alexander Malyshev 2016-02-17 13:13:54 UTC 
I got some new info here.

1) This issue is hardly reproducible with the logs because logging for each request highly slows down my server and request rate drops. I removed logs for all request and now I'm only logging the scenario when processor is recycled and put in RecycledProcessors map twice. And issue is reproducible very good with such logging.

2) Here is what happens. In very rare cases processor is recycled twice. Here is the info on how it gets recycled twice (note that I applied change from Mark's last comment - It does not help at all). I'm remembering stack trace line and thread name from last recycle call and if recycle is called once again, I'm logging it out:

Feb 17, 2016 MSK 03:49:37.417 PM http-nio-135.60.87.68-443-exec-50 org.apache.coyote.http11.AbstractHttp11Processor
SEVERE: Exception!!! Processor with request 676 to URI /viewer/wcc/app.swf is recycled twice.

First Calling method is: org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:953) by thread http-nio-135.60.87.68-443-exec-50
Current Calling method is: org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:785).

and right after that I'm getting usual NPEs and other exceptions related to this processor:

Feb 17, 2016 MSK 03:49:37.425 PM http-nio-135.60.87.68-443-exec-46 org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.. Request id: 676

java.lang.IllegalStateException: Unexpected state: headers already parsed. Buffer not recycled?
	at org.apache.coyote.http11.AbstractNioInputBuffer.parseHeaders(AbstractNioInputBuffer.java:375)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1034)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:686)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


Feb 17, 2016 MSK 03:49:37.427 PM http-nio-135.60.87.68-443-exec-46 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response. Request id: 676

java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:234)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:189)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:177)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:748)
	at org.apache.coyote.Response.action(Response.java:177)
	at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
	at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1818)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1157)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:686)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

Note that calling thread in both cases was http-nio-135.60.87.68-443-exec-50 - which most probably means it happened during the same AbstractConnectionHandler.process() call. I also noticed that it always happens in the very begining of my traffic run and first time issue happens with the request to static file (/viewer/wcc/app.swf). With the fact that one of the possible call paths to cancelledKey() method is through NioEndpoint.processSendfile() method - my opinion is that it's 90% related to send file fucntionality and special logic for that.
Comment 25 Alexander Malyshev 2016-02-17 13:17:10 UTC 
I will try to remember the whole stack trace of the first call to find out the actual call path - as there are a lot of possible call paths to cancelledKey() method.
Comment 26 Alexander Malyshev 2016-02-17 13:58:20 UTC 
Ok, I confirmed it's related to send file functionality:

Feb 17, 2016 MSK 04:31:03.077 PM http-nio-135.60.87.68-443-exec-25 org.apache.coyote.http11.AbstractHttp11Processor
SEVERE: Exception!!! Processor with request 219 to URI /viewer/wcc/app.swf is recycled twice.
First Calling stack trace is by thread http-nio-135.60.87.68-443-exec-25:
java.lang.Thread.getStackTrace(Thread.java:1552)
org.apache.coyote.http11.AbstractHttp11Processor.recycle(AbstractHttp11Processor.java:1869)
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.release(Http11NioProtocol.java:199)
org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:953)
org.apache.tomcat.util.net.NioEndpoint$Poller.processSendfile(NioEndpoint.java:1212)
org.apache.coyote.http11.Http11NioProcessor.breakKeepAliveLoop(Http11NioProcessor.java:285)
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1186)
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:686)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:745)
Current Calling method is: org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:785)

Feb 17, 2016 MSK 04:31:03.099 PM http-nio-135.60.87.68-443-exec-26 org.apache.coyote.http11.Http11NioProcessor
INFO: Error parsing HTTP request header
 Note: further occurrences of HTTP header parsing errors will be logged at DEBUG level.. Request id: 219

java.lang.IllegalStateException: Unexpected state: headers already parsed. Buffer not recycled?
	at org.apache.coyote.http11.AbstractNioInputBuffer.parseHeaders(AbstractNioInputBuffer.java:375)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1034)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:686)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)


Feb 17, 2016 MSK 04:31:03.100 PM http-nio-135.60.87.68-443-exec-26 org.apache.coyote.http11.Http11NioProcessor
SEVERE: Error finishing response. Request id: 219

java.lang.NullPointerException
	at org.apache.coyote.http11.InternalNioOutputBuffer.flushBuffer(InternalNioOutputBuffer.java:234)
	at org.apache.coyote.http11.InternalNioOutputBuffer.addToBB(InternalNioOutputBuffer.java:189)
	at org.apache.coyote.http11.InternalNioOutputBuffer.commit(InternalNioOutputBuffer.java:177)
	at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:748)
	at org.apache.coyote.Response.action(Response.java:177)
	at org.apache.coyote.http11.AbstractOutputBuffer.endRequest(AbstractOutputBuffer.java:369)
	at org.apache.coyote.http11.AbstractHttp11Processor.endRequest(AbstractHttp11Processor.java:1818)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1157)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:686)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

If additional info is enabled to find the root cause, please let me know.
Comment 27 Mark Thomas 2016-02-18 16:47:55 UTC 
Thanks for all your research. Once I knew it was sendfile, tracking it down was fairly simple. I have fixed this in 8.0.x for 8.0.33. Please test and feel free to re-open if it isn't fixed.
Comment 28 Mark Thomas 2016-02-18 19:17:57 UTC 
Fix back-ported to 7.0.x for 7.0.69 onwards and to 6.0.x for 6.0.46 onwards.
Comment 29 Aurélien 2017-04-26 08:45:11 UTC 
I have encountered a very similar issue on Tomcat 9.0.0.M1: 
- first "CoyoteAdapter.checkRecycled Encountered a non-recycled request and recycled it forcedly",
- then a lof of 400 errors with the tomcat error "Http11Processor.endRequest Error finishing response java.lang.NullPointerException"

I would like to switch back to the stable version of Tomcat 8.5.14. However when I look at the changelog, I cannot see that this issue is corrected in the 8.5.X branch (nor in the 9.0.0.X branch).

Is my bug another issue or is this bug not yet backport to this branches?
Thank you for your precisions.
Comment 30 Mark Thomas 2017-04-26 09:09:42 UTC 
Yes, the original bug is fixed in all 8.5.x and 9.0.x releases. It doesn't appear in the changelog because it was fixed before development of those branches started.
Comment 31 neerajad2 2018-07-20 20:12:48 UTC 
(In reply to Aurélien from comment #29)
> I have encountered a very similar issue on Tomcat 9.0.0.M1: 
> - first "CoyoteAdapter.checkRecycled Encountered a non-recycled request and
> recycled it forcedly",
> - then a lof of 400 errors with the tomcat error "Http11Processor.endRequest
> Error finishing response java.lang.NullPointerException"
> 
> I would like to switch back to the stable version of Tomcat 8.5.14. However
> when I look at the changelog, I cannot see that this issue is corrected in
> the 8.5.X branch (nor in the 9.0.0.X branch).
> 
> Is my bug another issue or is this bug not yet backport to this branches?
> Thank you for your precisions.



Hi,

I am encountering the same issue with Tomcat 9.0.0.M1. Please let me know if you were able to fix it