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.
Created attachment 23308 [details] Test war to reproduce the problem
Created attachment 23309 [details] Original Tomcat log with connectors set to trace
Created attachment 23310 [details] Tomcat log with additional stacks
Created attachment 23311 [details] Servlet log, so that one can compare the timestamps
I used the default server.xml.
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.
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
Please ignore comment #7. It wasn't meant to be added to this ticket. Sorry for the noise.
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.
(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.
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.
Created attachment 23314 [details] Patch using a guard to prevent duplicate headers flushing in OutputBuffer
Comment on attachment 23314 [details] Patch using a guard to prevent duplicate headers flushing in OutputBuffer This patch is wrong.
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?
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.
This has been fixed in 5.5.x and will be included in 5.5.28 onwards.