Right I can confirm the regression.
We'll withdraw 1.2.29 and immediately release 1.2.30

Created attachment 25064 [details]
1.2.30-dev for x64

Could you confirm this version is OK before I tag 1.2.30
I have confirmed, but would like your confirmation as well

Use the version from
http://tomcat.apache.org/dev/dist/tomcat-connectors/jk/binaries/win64/jk-1.2.30/
That contains a fixed version

This one works for all the cases I had available to throw at it, with any of the three tomcat apr processors.

Thanks so much for fixing this so quickly.


The only oddity I see now is that certain GET requests to servlets cause isapi log message pairs like the following. Do you know offhand, are these likely to be a defective servlet, or configuration (improper timeouts?), or something else?

[Sat Feb 27 15:30:54.827 2010] [4024:2796] [info]  ajp_service::jk_ajp_common.c (2540): (nfx1) sending request to tomcat failed (recoverable), because of server error (attempt=1)

[Sat Feb 27 15:30:55.015 2010] [4024:2796] [info] ajp_send_request::jk_ajp_common.c (1490): (nfx1) did not receive END_RESPONSE, closing socket -1

I assume there are not other info, warn or error log messages directly around those cited. In this case I only found two possible reasons, both detected in ajp_process_callback():

1) The backend tells us to send the response header stop the client, but we already were told to do that directly before:

1784     case JK_AJP13_SEND_HEADERS:
1785         {
1786             int rc;
1787             jk_res_data_t res;
1788             if (ae->last_op == JK_AJP13_SEND_HEADERS) {
1789                 /* Do not send anything to the client.
1790                  * Backend already send us the headers.
1791                  */
1792                 if (JK_IS_DEBUG_LEVEL(l)) {
1793                     jk_log(l, JK_LOG_DEBUG,
1794                            "Already received AJP13_SEND HEADERS");
1795                 }
1796                 JK_TRACE_EXIT(l);
1797                 return JK_AJP13_ERROR;
1798             }

or

2) the backend tells us to return a body response packet to the client, although we didn't yet receive the response headers from the backend.

1836     case JK_AJP13_SEND_BODY_CHUNK:
1837         if (ae->last_op == JK_AJP13_FORWARD_REQUEST) {
1838             /* We have just send a request but received something
1839              * that probably originates from buffered response.
1840              */
1841             if (JK_IS_DEBUG_LEVEL(l)) {
1842                 jk_log(l, JK_LOG_DEBUG,
1843                        "Unexpected AJP13_SEND_BODY_CHUNK");
1844             }
1845             JK_TRACE_EXIT(l);
1846             return JK_AJP13_ERROR;
1847         }

All other possible reasons for those log messages would already log something about the precise reason directly before at least with log level info, most of the times even error.

To decide, which of the two remaining cases it is, you might temporarily increase the log level in lines 1793 and 1842 in jk_ajp_common.c from JK_LOG_DEBUG to JK_LOG_INFO (or JK_LOG_ERROR) and remove the surrounding "if (JK_IS_DEBUG_LEVEL(l)) { ... }".

Regards,

Rainer

Rainer, thank you for the analysis.

I find that the application (Apache Axis2) sends a gratuitous "flush" or two after the end-of-response message. As you know, flush is sent as a zero-length send-body-chunk message. Apparently the jk sees this a protocol violation.

There must be a race in the jk between tearing down the finished request and posting received data to it, because when I single-step the Tomcat, the isapi doesn't complain about it.

Since (so far) I only see this behavior on infrequent administrative requests, and it doesn't effect the results or reliability of the server, I am not going to worry about it.

Thanks,
Bruce

Actually, Axis2 flushes and closes the stream twice on the offending operation, so there is an extra end-of-response packet out there. I think the extra packet waits in the socket, so the next request on that socket fails the first attempt. I'll file a report at their jira.