Bug 46770 - Headers are send duplicate
Headers are send duplicate
Status: RESOLVED FIXED
Product: Tomcat 5
Classification: Unclassified
Component: Connector:AJP
5.5.27
All All
: P2 normal (vote)
: ---
Assigned To: Tomcat Developers Mailing List
: PatchAvailable
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2009-02-25 18:15 UTC by Rainer Jung
Modified: 2009-04-09 04:12 UTC (History)
0 users



Attachments
Test war to reproduce the problem (352.70 KB, application/octet-stream)
2009-02-25 18:22 UTC, Rainer Jung
Details
Original Tomcat log with connectors set to trace (2.76 KB, application/octet-stream)
2009-02-25 18:23 UTC, Rainer Jung
Details
Tomcat log with additional stacks (23.08 KB, application/octet-stream)
2009-02-25 18:24 UTC, Rainer Jung
Details
Servlet log, so that one can compare the timestamps (511 bytes, application/octet-stream)
2009-02-25 18:24 UTC, Rainer Jung
Details
Patch using a guard to prevent duplicate headers flushing in OutputBuffer (1.19 KB, patch)
2009-02-26 05:04 UTC, Rainer Jung
Details | Diff
Patch using a guard to prevent duplicate headers flushing in OutputBuffer (1.42 KB, patch)
2009-02-26 08:37 UTC, Rainer Jung
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Rainer Jung 2009-02-25 18:15:50 UTC
This is a regression between 5.5.25 (OK) and 5.5.26 (broken).
The same problem exists in 5.5.27 and in 5.5 trunk as of today.
It does not exist in 6.0.18.

I will attach a test case DoubleResponse.war. After deploying it, cou can simply call /DoubleResponse/.

The code is contained in the war. It is simple and basically does:

    response.setContentLength(0);
    response.getOutputStream().print("");
    response.flushBuffer();

This leads to sending the request headers twice when used with the AJP connector (tested without APR). With HTTP it works.

You can observe the double sending by either sniffing between web server and Tomcat, or setting JkLogLevel to debug.

Since mod_jk 1.2.27 we do no longer allow duplicate header sending.

I increased the log level of some connector packages. One can see a duplicate COMMIT block in the attached log lines. To make the analysis easier I added output of the method stack for some of those lines. Both logs are attached.
Comment 1 Rainer Jung 2009-02-25 18:22:54 UTC
Created attachment 23308 [details]
Test war to reproduce the problem
Comment 2 Rainer Jung 2009-02-25 18:23:39 UTC
Created attachment 23309 [details]
Original Tomcat log with connectors set to trace
Comment 3 Rainer Jung 2009-02-25 18:24:04 UTC
Created attachment 23310 [details]
Tomcat log with additional stacks
Comment 4 Rainer Jung 2009-02-25 18:24:35 UTC
Created attachment 23311 [details]
Servlet log, so that one can compare the timestamps
Comment 5 Rainer Jung 2009-02-25 18:24:59 UTC
I used the default server.xml.
Comment 6 Rainer Jung 2009-02-25 19:02:30 UTC
The problem seems to come from

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

which changed flush handling in MsgContext. Since there is no BZ related to this fix, it is not clear to me, what the right solution is. After reverting this change, the problem is gone.

I will ping Bill Barker, who added this fix.
Comment 7 Rainer Jung 2009-02-25 19:13:01 UTC
Ursache ist der Patch

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

der von Bill Barker in 5.5.26 eingebracht wurde. Sobald dieser herausgenommen wird, ist auch das Problem der doppelten Headers im Testcase weg.

Wir kontaktieren Bill gerade, um sein Ursprungsproblem zu verstehen und einen besseren Patch dafür zu finden.

Als Workaround könnten wir eine einzelne Klasse ohne den oben angegebenen kaputten Patch bauen und Ihnen zur Verfügung stellen. Die Klasse wird dann einfach in server/classes abgelegt und überlagert die im Jar-File enthaltene.

Gruß

Rainer Jung
Comment 8 Rainer Jung 2009-02-25 19:18:24 UTC
Please ignore comment #7. It wasn't meant to be added to this ticket. Sorry for the noise.
Comment 9 william.barker 2009-02-25 19:45:52 UTC
The original problem was that when client-flush was implemented in mod_jk, the default connector didn't look to see that the headers were sent as well.  Now the headers are sent, but the CoyoteRequest isn't marked as committed.

The simplest fix is to change R580815 to do res.sendHeaders(...) instead of calling the ActionHook.  But I'm not certain that it's the best fix, since I haven't looked at it very long.  I'd +1 this change if you need it in a hurry, since I'm a bit short on spare cycles at the moment.

Of course the other place to change this is to call res.setCommitted(true) from JkInputStream.appendHead(...).  As I said, haven't looked at it long enough to know which is better.

One thing that worries me is that you don't see it in 6.0, since I can't find the difference in the o.a.jk Connectors.
Comment 10 Rainer Jung 2009-02-26 02:59:14 UTC
(In reply to comment #9)
> The original problem was that when client-flush was implemented in mod_jk, the
> default connector didn't look to see that the headers were sent as well.  Now
> the headers are sent, but the CoyoteRequest isn't marked as committed.

I see, good to know.

> The simplest fix is to change R580815to do res.sendHeaders(...) instead of
> calling the ActionHook.  But I'm not certain that it's the best fix, since I
> haven't looked at it very long.  I'd +1 this change if you need it in a hurry,
> since I'm a bit short on spare cycles at the moment.
> 
> Of course the other place to change this is to call res.setCommitted(true) from
> JkInputStream.appendHead(...).  As I said, haven't looked at it long enough to
> know which is better.

I'll try a couple of options.

> One thing that worries me is that you don't see it in 6.0, since I can't find
> the difference in the o.a.jk Connectors.

Yes, I retested with 6.0.18, 6.0 HEAD and trunk. None of them shows the problem. So I'll also investigate code differences.
Comment 11 Rainer Jung 2009-02-26 05:02:48 UTC
I found the reason, why 6.0 and trunk behave better. It's a side effect of r411577. It replaces INITIAL_STATE with an variable initial. When FLUSH sends out the headers, initial is used as a guard against duplicate sending of the headers.

I will attach a patch which is a direct port of this side effect to TC 5.5.
Comment 12 Rainer Jung 2009-02-26 05:04:00 UTC
Created attachment 23314 [details]
Patch using a guard to prevent duplicate headers flushing in OutputBuffer
Comment 13 Rainer Jung 2009-02-26 07:27:07 UTC
Comment on attachment 23314 [details]
Patch using a guard to prevent duplicate headers flushing in OutputBuffer

This patch is wrong.
Comment 14 Rainer Jung 2009-02-26 07:56:51 UTC
My test for the proposed patch was wrong.

The situation is (as always) more complicated:

The flushing does not commit the response.

Remember, that the servvlet does:

    response.setContentLength(0);
    response.getOutputStream().print("");
    response.flushBuffer();

flushBuffer() triggers OutputBuffer.doFlush(). In there we already have state == CHAR_STATE. In this case we do not call coyoteResponse.sendHeaders() and thus the coyoteResponse doesn't get committed.

Then we trigger ACTION_CLIENT_FLUSH.

By revision r580815, we immediately do ACTION_COMMIT inside ACTION_CLIENT_FLUSH.

This in turn calls JkInputStream.appendHead(), which sends the headers without committing.

Later from Response.finishResponse() we do ACTION_CLOSE, which in turn again does ACTION_COMMIT and we send out the headers a second time.

I guess at least at the end of the first ACTION_COMMIT we should have called coyoteResponse.setCommitted(true). The question is: where exactly should we do that?
Comment 15 Rainer Jung 2009-02-26 08:37:14 UTC
Created attachment 23316 [details]
Patch using a guard to prevent duplicate headers flushing in OutputBuffer

This time the patch is a little more serious and unfortunately not so easy to review. It is still a partial backport from TC 6. I hope I did the tests correct now. Any comments welcome.
Comment 16 Mark Thomas 2009-04-09 04:12:20 UTC
This has been fixed in 5.5.x and will be included in 5.5.28 onwards.