Bug 63626

The change is also available at: https://github.com/michael-o/httpd/tree/BZ-63626/2.4.x

This was the thread that resulted when the backport was proposed:

https://mail-archives.apache.org/mod_mbox/httpd-dev/201305.mbox/%3c518A0304.9050707@apache.org%3e

It got bogged down in what the effect would be if applied to the stable v2.4 branch.

Can you confirm more detail on the problem you're seeing that this patch is solving? Or is it just the case that it's wrong as per the RFC (which it is).

My initial problem is described in https://www.mail-archive.com/users@tomcat.apache.org/msg132332.html.

I will try to summarize:

HTTPd responded HTTP_SERVICE_UNAVAILABLE, Tomcat did not respond it time, but after ProxyTimeout has elapsed with 500 because of a broken pipe. Our API users were surprised just like me because the service was up and running, but external resources (some domain controllers) did not respond in time. The service *was* available. It took me some time to understand the root cause. HTTP_GATEWAY_TIME_OUT would have made it easiser/faster to understand.

It shall be possible to clearly understand whether an upstream server did not respond in time, did not respond to a connect() (unavailable) or send a bad response (bad gateway).

Look at the first hunk:
> diff --git a/modules/proxy/mod_proxy_http.c b/modules/proxy/mod_proxy_http.c
> index ec1e042c4e..6667931efd 100644
> --- a/modules/proxy/mod_proxy_http.c
> +++ b/modules/proxy/mod_proxy_http.c
> @@ -1255,7 +1255,7 @@ int ap_proxy_http_process_response(proxy_http_req_t *req)
>                  apr_table_setn(r->notes, "proxy_timedout", "1");
>                  ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, APLOGNO(01103) "read timeout");
>                  if (do_100_continue) {
> -                    return ap_proxyerror(r, HTTP_SERVICE_UNAVAILABLE, "Timeout on 100-Continue");
> +                    return ap_proxyerror(r, HTTP_GATEWAY_TIME_OUT, "Timeout on 100-Continue");

"proxy_timedout" is set, but the status code does not reflect that.

Moreover, as you have already noticed, it violates RFC 7231, 6.6.

(In reply to Michael Osipov from comment #3)
> My initial problem is described in
> https://www.mail-archive.com/users@tomcat.apache.org/msg132332.html.
> 
> I will try to summarize:
> 
> HTTPd responded HTTP_SERVICE_UNAVAILABLE, Tomcat did not respond it time,
> but after ProxyTimeout has elapsed with 500 because of a broken pipe. Our
> API users were surprised just like me because the service was up and
> running, but external resources (some domain controllers) did not respond in
> time. The service *was* available. It took me some time to understand the
> root cause. HTTP_GATEWAY_TIME_OUT would have made it easiser/faster to
> understand.
> 
> It shall be possible to clearly understand whether an upstream server did
> not respond in time, did not respond to a connect() (unavailable) or send a
> bad response (bad gateway).
> 
> Look at the first hunk:
> > diff --git a/modules/proxy/mod_proxy_http.c b/modules/proxy/mod_proxy_http.c
> > index ec1e042c4e..6667931efd 100644
> > --- a/modules/proxy/mod_proxy_http.c
> > +++ b/modules/proxy/mod_proxy_http.c
> > @@ -1255,7 +1255,7 @@ int ap_proxy_http_process_response(proxy_http_req_t *req)
> >                  apr_table_setn(r->notes, "proxy_timedout", "1");
> >                  ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, APLOGNO(01103) "read timeout");
> >                  if (do_100_continue) {
> > -                    return ap_proxyerror(r, HTTP_SERVICE_UNAVAILABLE, "Timeout on 100-Continue");
> > +                    return ap_proxyerror(r, HTTP_GATEWAY_TIME_OUT, "Timeout on 100-Continue");
> 
> "proxy_timedout" is set, but the status code does not reflect that.
> 
> Moreover, as you have already noticed, it violates RFC 7231, 6.6.

In that particular code path the error code is correct (see the do_100_continue condition above which means that the server did only "ping" the backend server whether it is responsive or not but did not process the 'real' request yet). The reverse proxy or gateway tried to contact the backend and found it unavailable. This allows to sent non idempotent requests to a different backend in a load balanced / fail over scenario. HTTP_GATEWAY_TIME_OUT means the request was started on the backend and we cannot resent a non idempotent request.

I do not understand your explanation. The difference between service unailable and timeout is that service unavailable says connect() did not work which the latter fails on read().

In that particular case the connection has been established, a client sent "Expect: 100-continue" and the proxy is now waiting for a response.
It feels counterintuitive to write "timeout" to the logs, but tell the client that the service is not available. That is not true. It would only be true if a worker cannot connect to it.

Citing:

6.6.5.  504 Gateway Timeout

   The 504 (Gateway Timeout) status code indicates that the server,
   while acting as a gateway or proxy, did not receive a timely response
   from an upstream server it needed to access in order to complete the
   request.

...this is what happens.

Maybe we should ask Julian Reschke about this.

AIUI, the purpose of the 100-continue mechanism is to ping the service, as opposed to ping the (TCP-)connection.
In this case the client sent the HTTP header with "Expect: 100-continue", mod_proxy_http forwarded it (TCP connect/reuse works) but did *not* respond with the interim "100 continue" message yet (since httpd-2.4.41 and bug 60330 ;) ).
So no body has been engaged yet and the service can be considered unavailable, i.e. the client or mod_proxy can send the non-idempotent request elsewhere since the previous attempt was consciously incomplete.

Also note that the timeout can be reduced in this case, using mod_proxy's ping= parameter.

(In reply to Yann Ylavic from comment #6)
> AIUI, the purpose of the 100-continue mechanism is to ping the service, as
> opposed to ping the (TCP-)connection.
> In this case the client sent the HTTP header with "Expect: 100-continue",
> mod_proxy_http forwarded it (TCP connect/reuse works) but did *not* respond
> with the interim "100 continue" message yet (since httpd-2.4.41 and bug
> 60330 ;) ).
> So no body has been engaged yet and the service can be considered
> unavailable, i.e. the client or mod_proxy can send the non-idempotent
> request elsewhere since the previous attempt was consciously incomplete.

How am I then supposed to differ between gateway timeout and service unavailable exactly in the case you have described for bug 60330? I understand that the ping is different (internal) in nature, but technically the same. As a server admin I must be able to see a difference in the logs for this.

From an administrator POV, I agree that having a separate logno/message for the 100-continue timeout case makes sense, but it seems to be the case already no?
In the error_log ISTM that first AH01102 appears with "The timeout specified has expired", and then AH00898 with "503 Proxy Error returned by..." in the 100-continue case or "502 Proxy Error..." otherwise.

Comment on attachment 36700 [details]
Patch for timeouts

From your patch..

>diff --git a/modules/proxy/mod_proxy_http.c b/modules/proxy/mod_proxy_http.c
>index ec1e042c4e..6667931efd 100644
>--- a/modules/proxy/mod_proxy_http.c
>+++ b/modules/proxy/mod_proxy_http.c
[...]
>@@ -1314,7 +1314,7 @@ int ap_proxy_http_process_response(proxy_http_req_t *req)
>                                    " failed.",
>                                    backend->hostname, backend->port);
>             }
>-            return ap_proxyerror(r, HTTP_BAD_GATEWAY,
>+            return ap_proxyerror(r, HTTP_GATEWAY_TIME_OUT,
>                                  "Error reading from remote server");
>         }
>         /* XXX: Is this a real headers length send from remote? */

That hunk should probably be:
+            return ap_proxyerror(r, APR_STATUS_IS_TIMEUP(rc)
+                                        ? HTTP_GATEWAY_TIME_OUT
+                                        : HTTP_BAD_GATEWAY,
                                  "Error reading from remote server");
because 504 is not always relevent here, I think.

The you could differentiate between "{502,503,504} Proxy Error..." in AH00898.

Created attachment 36974 [details]
Patch for timeouts

(In reply to Yann Ylavic from comment #10)
> Comment on attachment 36700 [details]
> Patch for timeouts
> 
> From your patch..
> 
> >diff --git a/modules/proxy/mod_proxy_http.c b/modules/proxy/mod_proxy_http.c
> >index ec1e042c4e..6667931efd 100644
> >--- a/modules/proxy/mod_proxy_http.c
> >+++ b/modules/proxy/mod_proxy_http.c
> [...]
> >@@ -1314,7 +1314,7 @@ int ap_proxy_http_process_response(proxy_http_req_t *req)
> >                                    " failed.",
> >                                    backend->hostname, backend->port);
> >             }
> >-            return ap_proxyerror(r, HTTP_BAD_GATEWAY,
> >+            return ap_proxyerror(r, HTTP_GATEWAY_TIME_OUT,
> >                                  "Error reading from remote server");
> >         }
> >         /* XXX: Is this a real headers length send from remote? */
> 
> That hunk should probably be:
> +            return ap_proxyerror(r, APR_STATUS_IS_TIMEUP(rc)
> +                                        ? HTTP_GATEWAY_TIME_OUT
> +                                        : HTTP_BAD_GATEWAY,
>                                   "Error reading from remote server");
> because 504 is not always relevent here, I think.
> 
> The you could differentiate between "{502,503,504} Proxy Error..." in
> AH00898.

Sorry for responding so late. I agree, this should be generalized. Patch has been updated.

(In reply to Michael Osipov from comment #12)
> 
> Sorry for responding so late. I agree, this should be generalized. Patch has
> been updated.

Some comments:

1. The patch seems to be against 2.4.x. We need a patch against trunk first. Afterwards this code can be backported to the stable branch.

2. As said in #4 the HTTP_SERVICE_UNAVAILABLE is correct here and must stay as it ensures that a correct failover / retry happens in case the existing connection was just dead.

--- a/modules/proxy/mod_proxy_http.c
+++ b/modules/proxy/mod_proxy_http.c
@@ -1255,7 +1255,7 @@ int ap_proxy_http_process_response(proxy_http_req_t *req)
                 apr_table_setn(r->notes, "proxy_timedout", "1");
                 ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, APLOGNO(01103) "read timeout");
                 if (do_100_continue) {
-                    return ap_proxyerror(r, HTTP_SERVICE_UNAVAILABLE, "Timeout on 100-Continue");
+                    return ap_proxyerror(r, HTTP_GATEWAY_TIME_OUT, "Timeout on 100-Continue");
                 }
             }
             /*

3. ap_proxy_backend_broke is a generic procedure that is also called in cases where the cause of the failure is not a timeout. Hence the status code cannot be just changed. The patch would need to be more complex. As ap_proxy_backend_broke is an API function the way forward would be to create an ap_proxy_backend_broke_ex which has an additional parameter for the status code and hence can be called with HTTP_GATEWAY_TIME_OUT as status code where needed and change ap_proxy_backend_broke to call ap_proxy_backend_broke_ex with HTTP_BAD_GATEWAY as status code.

diff --git a/modules/proxy/proxy_util.c b/modules/proxy/proxy_util.c
index 5482ab8a48..1177173968 100644
--- a/modules/proxy/proxy_util.c
+++ b/modules/proxy/proxy_util.c
@@ -3305,7 +3305,7 @@ PROXY_DECLARE(void) ap_proxy_backend_broke(request_rec *r,
      */
     if (r->main)
         r->main->no_cache = 1;
-    e = ap_bucket_error_create(HTTP_BAD_GATEWAY, NULL, c->pool,
+    e = ap_bucket_error_create(HTTP_GATEWAY_TIME_OUT, NULL, c->pool,
                                c->bucket_alloc);
     APR_BRIGADE_INSERT_TAIL(brigade, e);
     e = apr_bucket_eos_create(c->bucket_alloc);

(In reply to Ruediger Pluem from comment #13)
> (In reply to Michael Osipov from comment #12)
> > 
> > Sorry for responding so late. I agree, this should be generalized. Patch has
> > been updated.
> 
> Some comments:
> 
> 1. The patch seems to be against 2.4.x. We need a patch against trunk first.
> Afterwards this code can be backported to the stable branch.

No problem.

> 2. As said in #4 the HTTP_SERVICE_UNAVAILABLE is correct here and must stay
> as it ensures that a correct failover / retry happens in case the existing
> connection was just dead.

Reread and understand your reasoning. I think you have a typo:
> This allows to sent non idempotent requests to a different backend in a load balanced / fail over scenario.

Did you mean idemponent? Otherwise it does not make any sense to retry a request.

Can we add a comment to the do_100_continue to clearly document this is a ping and not a real request?

> 3. ap_proxy_backend_broke is a generic procedure that is also called in
> cases where the cause of the failure is not a timeout. Hence the status code
> cannot be just changed. The patch would need to be more complex. As
> ap_proxy_backend_broke is an API function the way forward would be to create
> an ap_proxy_backend_broke_ex which has an additional parameter for the
> status code and hence can be called with HTTP_GATEWAY_TIME_OUT as status
> code where needed and change ap_proxy_backend_broke to call
> ap_proxy_backend_broke_ex with HTTP_BAD_GATEWAY as status code.
> 
> diff --git a/modules/proxy/proxy_util.c b/modules/proxy/proxy_util.c
> index 5482ab8a48..1177173968 100644
> --- a/modules/proxy/proxy_util.c
> +++ b/modules/proxy/proxy_util.c
> @@ -3305,7 +3305,7 @@ PROXY_DECLARE(void) ap_proxy_backend_broke(request_rec
> *r,
>       */
>      if (r->main)
>          r->main->no_cache = 1;
> -    e = ap_bucket_error_create(HTTP_BAD_GATEWAY, NULL, c->pool,
> +    e = ap_bucket_error_create(HTTP_GATEWAY_TIME_OUT, NULL, c->pool,
>                                 c->bucket_alloc);
>      APR_BRIGADE_INSERT_TAIL(brigade, e);
>      e = apr_bucket_eos_create(c->bucket_alloc);

Makes sense, will work on that.

(In reply to Michael Osipov from comment #14)
> (In reply to Ruediger Pluem from comment #13)

> 
> Reread and understand your reasoning. I think you have a typo:
> > This allows to sent non idempotent requests to a different backend in a load balanced / fail over scenario.
> 
> Did you mean idemponent? Otherwise it does not make any sense to retry a
> request.

No I did mean non idempotent, because the "pinging" via the expect header ensures that the request stays somewhat idempotent until we actually sent the body on a 100-continue reply by the backend. Hence we can try with the next backend or with the same backend if we suspect a stale tcp connection to be the cause of the issue. Once we start sending the body, we cannot retry.

Created attachment 37137 [details]
Patch for 2.4.x

Created attachment 37138 [details]
Patch for 2.4.x

Created attachment 37139 [details]
Patch for trunk

Rüdiger,

here they are. Both are very different because ap_proxy_backend_broke() is not used in trunk anymore in that spot. It has been removed in 9bc9d79079b. A sole backport of this would be incomplete in 2.4.x.