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?
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.
Created attachment 19609 [details] patch against current trunk to fix bug
fixed in trunk and forthcoming 2.2