|Summary:||Process Send File releases the same Http11Processor in two threads, leading to java.lang.IllegalStateException: Unexpected state: headers already parsed. Buffer not recycled?|
|Product:||Tomcat 8||Reporter:||Andrew Garland <andrew.garland>|
|Component:||Catalina||Assignee:||Tomcat Developers Mailing List <dev>|
Some pieces of the full trace showing the issue
Description Andrew Garland 2017-03-24 17:43:14 UTC
Created attachment 34876 [details] Some pieces of the full trace showing the issue This is a similar report to https://bz.apache.org/bugzilla/show_bug.cgi?id=58646 but whatever fix was done in that case does not prevent this issue. Basic outline: 1. thread http-nio-8080-exec-1 processes a request that will result in send file. It pops Http11Processor@8dc1458 from recycledProcessors 2. The send file action is completed in thread http-nio-8080-ClientPoller-0. Then that thread is done, it pushes Http11Processor@8dc1458 onto recycledProcessors 3. A few milliseconds later, http-nio-8080-exec-1 also pushes Http11Processor@8dc1458 onto recycledProcessors, so now that one processor is in the list of recycledProcessors twice 4. Eventually, two nio exec threads both pop that one instance off of recycledProcessors 4A. The second thread to use it throws 24-Mar-2017 12:08:08.093 INFO [http-nio-8080-exec-1] 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:554) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:683) 4B. The first thread, which completes after the second one, throws 24-Mar-2017 12:08:08.833 SEVERE [http-nio-8080-exec-7] 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:783) and then 24-Mar-2017 12:08:08.849 SEVERE [http-nio-8080-exec-7] 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.prepareResponse(Http11Processor.java:1288) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:254) at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1457) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:823)
Comment 1 Andrew Garland 2017-03-24 17:47:03 UTC
To me, there are two separate issues here: 1. The logic for pushing the processor back in send file case has some flaw. 2. RecycledProcessors should protect against the same instance being in the stack more than once, as a defense against this flaw or any future flaws that result in mistakenly putting the same processor in twice.
Comment 2 Mark Thomas 2017-03-24 20:32:00 UTC
Thanks for the report and especially the debug logs. I was able to pin-point the root cause very quickly from those. Are you able to build Tomcat from svn in order to confirm a fix?
Comment 3 Andrew Garland 2017-03-24 20:33:57 UTC
i haven't before, but I am sure I could :) Please point me at BUILD instructions.
Comment 4 Mark Thomas 2017-03-24 20:56:39 UTC
These are the instructions for 9.0.x https://svn.apache.org/viewvc/tomcat/trunk/BUILDING.txt?view=markup 8.5.x is very similar, just a different svn path and a different minimum Java version. Both 9.0.x and 8.5.x have the fix. I'm currently working on a back-port to 8.0.x.
Comment 5 Andrew Garland 2017-03-24 20:59:28 UTC
thanks for the info. Can you point me to the commit diff? Just curious.
Comment 7 Andrew Garland 2017-03-24 21:09:12 UTC
FYI, minor typo in changelog subsequent requests experiencing and <code>IllegalStateException</code>. "and" -> "an"
Comment 8 Mark Thomas 2017-03-24 21:16:18 UTC
8.0.x and earlier are not affected. This bug was introduced by the refactoring in 8.5.x onwards.
Comment 9 Andrew Garland 2017-03-24 21:29:46 UTC
Created attachment 34877 [details] Recoded RecycledProcessors The problem does not recur using the version built from trunk! Thanks for the rapid turnaround. I guess it will be a month or two before this is part of an official release? FYI, I had also prevented the problem by re-coding the RecycledProcessors class to check for existence before pushing onto the stack. This was quick and dirty and would not scale, but food for thought.
Comment 10 Mark Thomas 2017-03-24 21:33:09 UTC
We'll probably start the release process next week. It is normally started around the beginning of the every month but the first week of April is looking busy for me. We could delay it but there is enough in the changelog to justify a release.
Comment 11 Remy Maucherat 2017-03-24 21:49:29 UTC
(In reply to Andrew Garland from comment #9) > Created attachment 34877 [details] > Recoded RecycledProcessors > > The problem does not recur using the version built from trunk! Thanks for > the rapid turnaround. I guess it will be a month or two before this is part > of an official release? > > FYI, I had also prevented the problem by re-coding the RecycledProcessors > class to check for existence before pushing onto the stack. This was quick > and dirty and would not scale, but food for thought. And we're not going to do that :)
Comment 12 Mark Thomas 2017-03-27 10:34:48 UTC
Fixed in: - trunk for 9.0.0.M19 onwards - 8.5.x for 8.5.13 onwards