Bug 41644 - proxied HEAD requests "pause" when ProxyErrorOverride is enabled
Summary: proxied HEAD requests "pause" when ProxyErrorOverride is enabled
Status: RESOLVED FIXED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_proxy (show other bugs)
Version: 2.2.4
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords: PatchAvailable
Depends on:
Blocks:
 
Reported: 2007-02-16 09:28 UTC by Stuart Children
Modified: 2007-09-01 10:07 UTC (History)
1 user (show)



Attachments
patch against current 2.2.x HEAD to fix bug (599 bytes, patch)
2007-02-16 09:37 UTC, Stuart Children
Details | Diff
patch against current trunk to fix bug (599 bytes, patch)
2007-02-16 09:39 UTC, Stuart Children
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Stuart Children 2007-02-16 09:28:27 UTC
Spotted this during reproduction/testing of bug #39245

Set up Apache as a reverse proxy to some backend HTTP server:

    ProxyPass /rproxy http://localhost:12345
    ProxyPassReverse /rproxy http://localhost:12345

Now make a GET request via this to something that does not exist on the backend
server (so a 404 will be returned):

$ time curl --get http://localhost:2200/rproxy/n
I am an error from the backend.

real    0m0.009s
user    0m0.004s
sys     0m0.003s

And now a HEAD request:

gnl05024 ~ $ time curl --head http://localhost:2200/rproxy/
HTTP/1.1 404 Not Found
Date: Fri, 16 Feb 2007 16:47:15 GMT
Server: Apache/2.2.4 (Unix)
Last-Modified: Fri, 16 Feb 2007 13:33:42 GMT
ETag: "452dd8-20-6299980"
Accept-Ranges: bytes
Content-Length: 32
Content-Type: text/plain


real    0m0.010s
user    0m0.004s
sys     0m0.003s

All fine. Now add the following config to the frontend and repeat:

    ProxyErrorOverride On
    ErrorDocument 404 /error.txt

$ time curl --get http://localhost:2200/rproxy/notfound
I am an error from the frontend.

real    0m0.010s
user    0m0.004s
sys     0m0.005s

$ time curl --head http://localhost:2200/rproxy/notfound
HTTP/1.1 404 Not Found
Date: Fri, 16 Feb 2007 16:50:21 GMT
Server: Apache/2.2.4 (Unix)
Last-Modified: Fri, 16 Feb 2007 13:33:42 GMT
ETag: "452dd8-20-6299980"
Accept-Ranges: bytes
Content-Length: 32
Content-Type: text/plain


real    0m5.009s
user    0m0.005s
sys     0m0.002s

Whoops, we're getting blocked for 5s somewhere. Attaching a debugger during the
"pause" and obtaining a backtrace:

#0  0x001f2402 in __kernel_vsyscall ()
#1  0x00c7969b in poll () from /lib/libc.so.6
#2  0x0068e974 in apr_wait_for_io_or_timeout (f=0x0, s=0x9575a60, for_read=1)
    at support/unix/waitio.c:51
#3  0x0068a130 in apr_socket_recv (sock=0x9575a60, 
    buf=0x95c0350 "HTTP/1.1 404 Not Found\r\nDate: Fri, 16 Feb 2007 16:55:01
GMT\r\nServer: Apache/2.2.4 (Unix)\r\nLast-Modified: Fri, 16 Feb 2007 13:33:42
GMT\r\nETag: \"452dd8-20-6299980\"\r\nAccept-Ranges: bytes\r\nContent-Length:"..., 
    len=0xbf9d1f5c) at network_io/unix/sendrecv.c:87
#4  0x00ea17e7 in apr_bucket_socket_create () from /usr/lib/libaprutil-1.so.0
#5  0x080782c3 in ap_core_input_filter (f=0x95b4ee0, b=0x95b6220, 
    mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)
    at core_filters.c:245
#6  0x080865d4 in ap_get_brigade (next=0x95b4ee0, bb=0x95b6220, 
    mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)
    at util_filter.c:489
#7  0x0809a649 in ap_http_filter (f=0x95b6200, b=0x95b6220, 
    mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)
    at http_filters.c:349
#8  0x080865d4 in ap_get_brigade (next=0x95b6200, bb=0x95b6220, 
    mode=AP_MODE_READBYTES, block=APR_BLOCK_READ, readbytes=8192)
    at util_filter.c:489
#9  0x0809bdf8 in ap_discard_request_body (r=0x95b5170) at http_filters.c:1123
#10 0x00a771ad in ap_proxy_http_process_response (p=0x95b4310, r=0x95bc368, 
    backend=0x95a7a60, origin=0x95b4a88, conf=0x954f688, 
    server_portstr=0xbf9d430c ":2200") at mod_proxy_http.c:1576
#11 0x00a77679 in proxy_http_handler (r=0x95bc368, worker=0x954b5e0, 
    conf=0x954f688, url=0x95b4a78 "/notfound", proxyname=0x0, proxyport=0)
    at mod_proxy_http.c:1711
#12 0x00117d56 in proxy_run_scheme_handler (r=0x95bc368, worker=0x954b5e0, 
    conf=0x954f688, url=0x95bd44e "http://localhost:12345/notfound", 
    proxyhost=0x0, proxyport=0) at mod_proxy.c:1978
#13 0x00114dde in proxy_handler (r=0x95bc368) at mod_proxy.c:780
#14 0x08079edd in ap_run_handler (r=0x95bc368) at config.c:157
#15 0x0807a627 in ap_invoke_handler (r=0x95bc368) at config.c:372
#16 0x08098b64 in ap_process_request (r=0x95bc368) at http_request.c:258
#17 0x080956e4 in ap_process_http_connection (c=0x95b44e0) at http_core.c:184
#18 0x0808244f in ap_run_process_connection (c=0x95b44e0) at connection.c:43
#19 0x08082863 in ap_process_connection (c=0x95b44e0, csd=0x95b4348)
    at connection.c:178
#20 0x080b14b3 in child_main (child_num_arg=0) at prefork.c:640
#21 0x080b159d in make_child (s=0x9505c80, slot=0) at prefork.c:680
#22 0x080b1b44 in ap_mpm_run (_pconf=0x95010a8, plog=0x953f1a0, s=0x9505c80)
    at prefork.c:956
#23 0x08063476 in main (argc=2, argv=0xbf9d4824) at main.c:717

We can see it's within ap_discard_request_body() called towards the end of
ap_proxy_http_process_response() in mod_proxy_http. Looking at that code:

   if (conf->error_override) {
        /* the code above this checks for 'OK' which is what the hook expects */
        if (ap_is_HTTP_SUCCESS(r->status))
            return OK;
        else {
            /* clear r->status for override error, otherwise ErrorDocument
             * thinks that this is a recursive error, and doesn't find the
             * custom error page
             */
            int status = r->status;
            r->status = HTTP_OK;
            /* Discard body, if one is expected */
            if ((status != HTTP_NO_CONTENT) && /* not 204 */
                (status != HTTP_NOT_MODIFIED)) { /* not 304 */
               ap_discard_request_body(rp);
           }

So the first two ifs determine whether ProxyErrorOverride is On and the response
is an error. In this case we'll be ignoring the response data from the backend
server and planting our own ErrorDocument - so we need to read and discard it
here. However, we may not always have a body! 204 and 304 are already countered
for there as you can see. HEAD requests are not. In fact, earlier in
ap_proxy_http_process_response() we see a similar check:

        /* send body - but only if a body is expected */
        if ((!r->header_only) &&                   /* not HEAD request */
            !interim_response &&                   /* not any 1xx response */
            (r->status != HTTP_NO_CONTENT) &&      /* not 204 */
            (r->status != HTTP_NOT_MODIFIED)) {    /* not 304 */

So the appropriate fix would be to add a similar check of r->header_only to the
conditional on calling ap_discard_request_body().

NB: "ap_discard_request_body" is confusing in this context - it's the body (or
lack of) of the *response* coming back from the backend server that's being
dealt with here. Right?

This same logic appears in trunk, 2.2.x and 2.0.x (actually tested and
observered with current 2.2.x HEAD, 2.2.4 and 2.0.58). Interestingly, 2.0.x also
checks for HTTP_RESET_CONTENT - which is not something I've dealt with so can't
really comment on whether that should be there or not. RFC says "The response
MUST NOT include an entity." - not sure if that means message-body?
Comment 1 Stuart Children 2007-02-16 09:37:13 UTC
Created attachment 19608 [details]
patch against current 2.2.x HEAD to fix bug

With this patch applied to 2.2.x:

$ time curl --get http://localhost:2200/rproxy/notfound
I am an error from the frontend.

real	0m0.010s
user	0m0.004s
sys	0m0.003s

$ time curl --head http://localhost:2200/rproxy/notfound
HTTP/1.1 404 Not Found
Date: Fri, 16 Feb 2007 17:31:28 GMT
Server: Apache/2.2.4 (Unix)
Last-Modified: Fri, 16 Feb 2007 13:33:42 GMT
ETag: "452dd8-20-6299980"
Accept-Ranges: bytes
Content-Length: 32
Content-Type: text/plain


real	0m0.012s
user	0m0.004s
sys	0m0.004s

The "pause" has gone.
Comment 2 Stuart Children 2007-02-16 09:39:44 UTC
Created attachment 19609 [details]
patch against current trunk to fix bug
Comment 3 Nick Kew 2007-09-01 10:07:09 UTC
fixed in trunk and forthcoming 2.2