Bug 59649

Summary: org.apache.coyote.http11.Http11Processor.service Error parsing HTTP request header
Product: Tomcat 9 Reporter: ismeet <ismeet>
Component: CatalinaAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED WORKSFORME    
Severity: major CC: ismeet, zmircmircea
Priority: P2    
Version: 9.0.0.M6   
Target Milestone: -----   
Hardware: PC   
OS: All   

Description ismeet 2016-06-01 14:11:12 UTC
With this tomcat version. Working under stress with http POST calls being fired for uploading and downloading of files. After about 10 to 15 into the test we started seeing broken responses.

On investigating the logs we noticed below errors:

01-Jun-2016 18:52:16.153 INFO [http-nio-8080-exec-2] org.apache.coyote.http11.Http11Processor.service 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.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:589)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1002)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:788)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1485)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)

01-Jun-2016 18:52:16.154 SEVERE [http-nio-8080-exec-4] org.apache.coyote.http11.Http11Processor.service Error processing request
 java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:389)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1102)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:788)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1485)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)

01-Jun-2016 18:52:16.160 SEVERE [http-nio-8080-exec-4] org.apache.coyote.http11.Http11Processor.endRequest Error finishing response
 java.lang.NullPointerException
	at org.apache.coyote.http11.Http11OutputBuffer.commit(Http11OutputBuffer.java:351)
	at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:646)
	at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1785)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1143)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:788)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1485)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)
Comment 1 Mark Thomas 2016-06-01 15:09:43 UTC
Steps to reproduce please. We need the minimal possible test case that demonstrates the issue.
Comment 2 Mark Thomas 2016-06-01 15:10:14 UTC
Dropping severity to default.
Comment 3 Mircea 2016-08-24 12:05:04 UTC
I have just experienced this error with 8.5.4
Exactly identical logs.
The solution was to restart the server. I set the log level on DEBUG, so now I'll have more info when it happens again.
Comment 4 Mircea 2016-08-24 12:08:52 UTC
Here is my stacktrace with Tomcat 8.5.4. Seems to be almost identical:

2016-08-24 07:48:38,236 INFO  [http-nio-8080-exec-10] o.a.coyote.http11.Http11Processor DirectJDKLog.java:181 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.Http11InputBuffer.parseHeaders(Http11InputBuffer.java:587)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1010)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	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)
2016-08-24 07:48:38,255 ERROR [http-nio-8080-exec-6] o.a.c.c.C.[.[.[.[.w.w.a.b.p.ApiProjectList] DirectJDKLog.java:181 Servlet.service() for servlet [dk.wordmaps.wordmaps4.api.boundary.project.ApiProjectList] in context with path [/api] threw exception
java.lang.NullPointerException: null
	at org.apache.catalina.connector.Request.getServletContext(Request.java:1618)
	at org.apache.catalina.connector.Request.getContextPath(Request.java:1975)
	at org.apache.catalina.connector.RequestFacade.getContextPath(RequestFacade.java:784)
	at dk.wordmaps.wordmaps4.api.boundary.util.security.StatelessSecurityFilter.doFilter(StatelessSecurityFilter.java:58)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at dk.wordmaps.wordmaps4.api.boundary.util.UTF8ServletFilter.doFilter(UTF8ServletFilter.java:25)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:522)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:256)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1110)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	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)
2016-08-24 07:48:38,256 ERROR [http-nio-8080-exec-6] o.a.c.c.C.[Catalina].[localhost] DirectJDKLog.java:181 Exception Processing null
java.lang.NullPointerException: null
	at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1519)
	at org.apache.catalina.connector.Request.setAttribute(Request.java:1505)
	at org.apache.catalina.core.StandardWrapperValve.exception(StandardWrapperValve.java:313)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:249)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:522)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
	at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:256)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1110)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	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)
2016-08-24 07:48:38,257 ERROR [http-nio-8080-exec-6] o.a.coyote.http11.Http11Processor DirectJDKLog.java:181 Error processing request
java.lang.NullPointerException: null
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:389)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1110)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	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)
2016-08-24 07:48:38,257 ERROR [http-nio-8080-exec-6] o.a.coyote.http11.Http11Processor DirectJDKLog.java:181 Error finishing response
java.lang.NullPointerException: null
	at org.apache.coyote.http11.Http11OutputBuffer.commit(Http11OutputBuffer.java:351)
	at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:658)
	at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1786)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:1149)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:785)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1425)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	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 5 Mircea 2016-08-24 12:20:26 UTC
As a continuation to my previous 2 comments...

The Tomcat 8.5.4 server was started yesterday at noon. Everything was fine.
By midnight, this error appeared, then most of the POST request triggered this error, even though the requests were totally identical to those sent between noon and midnight.

The solution was to restart Tomcat.
Comment 6 Mark Thomas 2016-08-24 12:59:37 UTC
Restoring state to NEDDINFO. Absent a way to reproduce this, there is little we can do to investigate.
Comment 7 Mark Thomas 2016-11-02 09:35:11 UTC
No test case has been provided so this is being resolved as works for me. Should a test case be provided that demonstrates this issue, it can be re-opened.