Bug 52547 - incorrect byeswritten log after completed async request under http1.0
Summary: incorrect byeswritten log after completed async request under http1.0
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 7.0.25
Hardware: All All
: P2 normal (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks: 52593
  Show dependency tree
 
Reported: 2012-01-27 19:43 UTC by David
Modified: 2012-02-03 17:57 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description David 2012-01-27 19:43:42 UTC
AbstractHttp11Processor does not call nextRequest() if the socket will be closed because keepAlive=false (i.e. http/1.0).

See line 1539 in
http://svn.apache.org/repos/asf/tomcat/tc7.0.x/tags/TOMCAT_7_0_25/java/org/apache/coyote/http11/AbstractHttp11Processor.java

Presumably the recycle() caused by the socket close is expected to subsume the behaviour of nextRequest()

But in AbstractOutputBuffer recycle() does not have byteCount = 0, whereas nextRequest() does.

See lines 260, 280 in
http://svn.apache.org/repos/asf/tomcat/tc7.0.x/tags/TOMCAT_7_0_25/java/org/apache/coyote/http11/AbstractOutputBuffer.java

The result is that the bytesWritten log of the following request will be incorrectly increased by the size of the async http/1.0 request
Comment 1 Mark Thomas 2012-01-28 20:34:04 UTC
Thanks for the report and the analysis. It appears that there is some code duplicated between recycle() and nextRequest() (nextRequest is a sub-set) so I also did a little refactoring. I'm always happy to reduce the number of lines of code we have to maintain.

The fix has been made to trunk and 7.0.x and will be included in 7.0.26 onwards.
Comment 2 David 2012-01-29 18:56:37 UTC
Thank you Mark.

Additionally, I think there is a "bug" in that the recycle() happens immediatley after the nextRequest() even when keepalive is true (I can see from an iptables log that the socket is not closed for another default 20 seconds).

See the event(...), asyncDispatch(...) and service(...) methods in
http://svn.apache.org/repos/asf/tomcat/tc7.0.x/trunk/java/org/apache/catalina/connector/CoyoteAdapter.java

Basically response.recycle() (when called because not dealing with async part of the request) calls outputBuffer.recycle() immediatley response processing is finished rather than just before the socket is actually closed.

So in an http/1.1 multi request-response (without a socket close) you still get both outputBuffer.nextRequest() and outputBuffer.recycle() called consecutvely at the end of each completed response process.

I can see that nextRequest(), recycle() should both exist, but only if recycle() really only happens at socket close as it's descriptive comment says. Otherwise it would be a (very minor) optimization to remove the (nearlly always present) duplicate calls.