mod_md: Honour the Retry-After header of ACME responses (BZ 70282)

Makefile.in

@@ -564,3 +564,10 @@ test/httpdunit: $(httpdunit_OBJECTS) $(PROGRAM_DEPENDENCIES) $(PROGRAM_OBJECTS)
 
 check-unittests: test/httpdunit
 	test/httpdunit
+
+# Regression test for md_util_parse_retry_after(), shared by mod_md and
+# a2md (see support/a2md/Makefile.in). Only in $(CHECK_TARGETS) when a2md
+# itself is enabled (support/a2md/config2.m4).
+.PHONY: check-retry-after
+check-retry-after:
+	cd support/a2md && $(MAKE) $(MFLAGS) check

changes-entries/md-retry-after.txt

@@ -0,0 +1,4 @@
+  *) mod_md: Honour the Retry-After header of ACME responses, as RFC 8555
+     recommends, when polling orders and authorizations, after finalizing an
+     order and when a request is rate limited. PR 70282
+     [Arturo Bernal]

include/ap_mmn.h

@@ -739,14 +739,19 @@
  * 20211221.31 (2.5.1-dev) Add ap_*_timingsafe() to httpd.h
  * 20211221.32 (2.5.1-dev) Add ap_cstr_stripws() to httpd.h
  * 20211221.33 (2.5.1-dev) Add ap_size_parameter_parse() to httpd.h
+ * 20211221.34 (2.5.1-dev) Add PROXY_WORKER_BEACON status bit to mod_proxy.h
+ * 20211221.35 (2.5.1-dev) Add the optional functions ap_mpm_note_extra_
+ *                         connection_added() and ap_mpm_note_extra_
+ *                         connection_removed(), and ap_mpm_wait_for_extra_
+ *                         connections(), to mpm_common.h
  */
 
 #define MODULE_MAGIC_COOKIE 0x41503235UL /* "AP25" */
 
 #ifndef MODULE_MAGIC_NUMBER_MAJOR
 #define MODULE_MAGIC_NUMBER_MAJOR 20211221
 #endif
-#define MODULE_MAGIC_NUMBER_MINOR 33             /* 0...n */
+#define MODULE_MAGIC_NUMBER_MINOR 35             /* 0...n */
 
 /**
  * Determine if the server's current MODULE_MAGIC_NUMBER is at least a

modules/md/md_acme.c

@@ -168,12 +168,27 @@ apr_status_t md_acme_init(apr_pool_t *p, const char *base,  int init_ssl)
     return init_ssl? md_crypt_init(p) : APR_SUCCESS;
 }
 
+apr_time_t md_acme_retry_after(const struct apr_table_t *headers)
+{
+    const char *value = headers? apr_table_get(headers, "Retry-After") : NULL;
+    const char *date = headers? apr_table_get(headers, "Date") : NULL;
+    apr_time_t now = apr_time_now();
+    apr_interval_time_t delay;
+
+    if (!value || APR_SUCCESS != md_util_parse_retry_after(&delay, value, date, now)) {
+        return 0;
+    }
+    return (now > 0 && delay > APR_INT64_MAX - now)? APR_INT64_MAX : now + delay;
+}
+
 static apr_status_t inspect_problem(md_acme_req_t *req, const md_http_response_t *res)
 {
     const char *ctype;
     md_json_t *problem = NULL;
     apr_status_t rv;
 
+    /* e.g. rateLimited, RFC 8555 6.6 */
+    req->result->retry_at = md_acme_retry_after(req->resp_hdrs);
     ctype = apr_table_get(req->resp_hdrs, "content-type");
     ctype = md_util_parse_ct(res->req->pool, ctype);
     if (ctype && !strcmp(ctype, "application/problem+json")) {
@@ -490,6 +505,7 @@ void md_acme_report_result(md_acme_t *acme, apr_status_t rv, struct md_result_t
     else {
         md_result_problem_set(result, acme->last->status, acme->last->problem, 
                               acme->last->detail, acme->last->subproblems);
+        result->retry_at = acme->last->retry_at;
     }
 }
 

modules/md/md_acme.h

@@ -168,6 +168,14 @@ apr_status_t md_acme_setup(md_acme_t *acme, struct md_result_t *result);
 
 void md_acme_report_result(md_acme_t *acme, apr_status_t rv, struct md_result_t *result);
 
+/**
+ * Get the local time a response asks the client to wait for with its
+ * Retry-After header (RFC 9110, 10.2.3). An HTTP-date is read against the
+ * Date header of the response, so a skewed clock of the server does not matter.
+ * @return the time, or 0 if there is no valid Retry-After
+ */
+apr_time_t md_acme_retry_after(const struct apr_table_t *headers);
+
 /**************************************************************************************************/
 /* account handling */
 

modules/md/md_acme_authz.c

@@ -111,6 +111,38 @@ static int copy_challenge_error(void *baton, size_t index, md_json_t *json)
     return 1;
 }
 
+typedef struct {
+    apr_pool_t *p;
+    md_acme_authz_t *authz;
+    md_json_t *json;
+} authz_get_ctx;
+
+static apr_status_t on_authz_got(md_acme_t *acme, apr_pool_t *p, const apr_table_t *hdrs,
+                                 md_json_t *body, void *baton)
+{
+    authz_get_ctx *ctx = baton;
+
+    (void)acme;
+    (void)p;
+    ctx->json = md_json_clone(ctx->p, body);
+    ctx->authz->retry_at = md_acme_retry_after(hdrs);
+    return APR_SUCCESS;
+}
+
+static apr_status_t authz_get_json(md_json_t **pjson, md_acme_authz_t *authz,
+                                   md_acme_t *acme, apr_pool_t *p)
+{
+    authz_get_ctx ctx;
+    apr_status_t rv;
+
+    ctx.p = p;
+    ctx.authz = authz;
+    ctx.json = NULL;
+    rv = md_acme_GET(acme, authz->url, NULL, on_authz_got, NULL, NULL, 1, &ctx);
+    *pjson = (APR_SUCCESS == rv)? ctx.json : NULL;
+    return rv;
+}
+
 apr_status_t md_acme_authz_update(md_acme_authz_t *authz, md_acme_t *acme, apr_pool_t *p)
 {
     md_json_t *json;
@@ -131,7 +163,8 @@ apr_status_t md_acme_authz_update(md_acme_authz_t *authz, md_acme_t *acme, apr_p
     err = "unable to parse response";
     log_level = MD_LOG_ERR;
 
-    if (APR_SUCCESS == (rv = md_acme_get_json(&json, acme, authz->url, 1, p))
+    authz->retry_at = 0;
+    if (APR_SUCCESS == (rv = authz_get_json(&json, authz, acme, p))
         && (s = md_json_gets(json, MD_KEY_STATUS, NULL))) {
 
         authz->domain = md_json_gets(json, MD_KEY_IDENTIFIER, MD_KEY_VALUE, NULL); 
@@ -215,8 +248,8 @@ static apr_status_t authz_http_set(md_acme_t *acme, apr_pool_t *p, const apr_tab
 
     (void)acme;
     (void)p;
-    (void)hdrs;
     (void)body;
+    ctx->authz->retry_at = md_acme_retry_after(hdrs);
     md_log_perror(MD_LOG_MARK, MD_LOG_TRACE1, 0, ctx->p, "updated authz %s", ctx->authz->url);
     return APR_SUCCESS;
 }

modules/md/md_acme_authz.h

@@ -53,6 +53,7 @@ struct md_acme_authz_t {
     const char *error_detail;
     const struct md_json_t *error_subproblems;
     struct md_json_t *resource;
+    apr_time_t retry_at;                /* not persisted: Retry-After of the last response */
 };
 
 #define MD_FN_HTTP01            "acme-http-01.txt"

modules/md/md_acme_drive.c

@@ -304,6 +304,8 @@ static apr_status_t csr_req(md_acme_t *acme, const md_http_response_t *res, void
     apr_status_t rv = APR_SUCCESS;
 
     (void)acme;
+    /* the order may still be processing, the CA says when to look again */
+    ad->order->retry_at = md_acme_retry_after(res->headers);
     location = apr_table_get(res->headers, "location");
     if (!location)
       return rv;

modules/md/md_acme_order.c

@@ -267,12 +267,13 @@ typedef struct {
     const char *ari_cert_id;
     apr_array_header_t *domains;
     md_result_t *result;
+    apr_time_t retry_at;
 } order_ctx_t;
 
 #define ORDER_CTX_INIT(ctx, p, o, a, n, d, pf, cid, r) \
     (ctx)->p = (p); (ctx)->order = (o); (ctx)->acme = (a); \
     (ctx)->name = (n); (ctx)->domains = d; (ctx)->profile = pf; \
-    (ctx)->ari_cert_id = cid;(ctx)->result = r
+    (ctx)->ari_cert_id = cid;(ctx)->result = r; (ctx)->retry_at = 0
 
 static apr_status_t identifier_to_json(void *value, md_json_t *json, apr_pool_t *p, void *baton)
 {
@@ -323,6 +324,7 @@ static apr_status_t on_order_upd(md_acme_t *acme, apr_pool_t *p, const apr_table
     }
 
     order_update_from_json(ctx->order, body, ctx->p);
+    ctx->order->retry_at = md_acme_retry_after(hdrs);
 out:
     return rv;
 }
@@ -391,7 +393,8 @@ apr_status_t md_acme_order_await_ready(md_acme_order_t *order, md_acme_t *acme,
     ORDER_CTX_INIT(&ctx, p, order, acme, md->name, NULL, NULL, NULL, result);
 
     md_result_activity_setn(result, "Waiting for order to become ready");
-    rv = md_util_try(await_ready, &ctx, 0, timeout, 0, 0, 1);
+    rv = md_util_try_with_retry_after(await_ready, &ctx, 0, timeout, 0, 0, 1,
+                                      &order->retry_at);
     md_result_log(result, MD_LOG_DEBUG);
     return rv;
 }
@@ -434,7 +437,8 @@ apr_status_t md_acme_order_await_valid(md_acme_order_t *order, md_acme_t *acme,
     ORDER_CTX_INIT(&ctx, p, order, acme, md->name, NULL, NULL, NULL, result);
 
     md_result_activity_setn(result, "Waiting for finalized order to become valid");
-    rv = md_util_try(await_valid, &ctx, 0, timeout, 0, 0, 1);
+    rv = md_util_try_with_retry_after(await_valid, &ctx, 0, timeout, 0, 0, 1,
+                                      &order->retry_at);
     md_result_log(result, MD_LOG_DEBUG);
     return rv;
 }
@@ -480,6 +484,9 @@ apr_status_t md_acme_order_start_challenges(md_acme_order_t *order, md_acme_t *a
                 if (APR_SUCCESS != rv) {
                     goto leave;
                 }
+                if (authz->retry_at > order->retry_at) {
+                    order->retry_at = authz->retry_at;
+                }
                 add_setup_token(order, setup_token);
                 md_acme_order_save(store, p, MD_SG_STAGING, md->name, order, 0);
                 break;
@@ -511,6 +518,7 @@ static apr_status_t check_challenges(void *baton, int attempt)
     apr_status_t rv = APR_SUCCESS;
     int i;
 
+    ctx->retry_at = 0;
     for (i = 0; i < ctx->order->authz_urls->nelts; ++i) {
         url = APR_ARRAY_IDX(ctx->order->authz_urls, i, const char*);
         md_log_perror(MD_LOG_MARK, MD_LOG_DEBUG, rv, ctx->p, "%s: check AUTHZ at %s (attempt %d)", 
@@ -525,6 +533,7 @@ static apr_status_t check_challenges(void *baton, int attempt)
                     break;
                 case MD_ACME_AUTHZ_S_PENDING:
                     rv = APR_EAGAIN;
+                    ctx->retry_at = authz->retry_at;
                     md_log_perror(MD_LOG_MARK, MD_LOG_DEBUG, rv, ctx->p, 
                                   "%s: status pending at %s", authz->domain, authz->url);
                     goto leave;
@@ -562,9 +571,13 @@ apr_status_t md_acme_order_monitor_authzs(md_acme_order_t *order, md_acme_t *acm
     apr_status_t rv;
 
     ORDER_CTX_INIT(&ctx, p, order, acme, md->name, NULL, NULL, NULL, result);
+    ctx.retry_at = order->retry_at;
 
     md_result_activity_printf(result, "Monitoring challenge status for %s", md->name);
-    rv = md_util_try(check_challenges, &ctx, 0, timeout, 0, 0, 1);
+    rv = md_util_try_with_retry_after(check_challenges, &ctx, 0, timeout, 0, 0, 1,
+                                      &ctx.retry_at);
+    /* that was the hint for the authorizations, not for the order */
+    order->retry_at = 0;
     md_log_perror(MD_LOG_MARK, MD_LOG_DEBUG, rv, p, "%s: checked authorizations", md->name);
     return rv;
 }

modules/md/md_acme_order.h

@@ -33,6 +33,7 @@ struct md_acme_order_t {
     apr_pool_t *p;
     const char *url;
     md_acme_order_st status;
+    apr_time_t retry_at;                /* not persisted: Retry-After of the last response */
     struct apr_array_header_t *authz_urls;
     struct apr_array_header_t *challenge_setups;
     struct md_json_t *json;

modules/md/md_acmev2_drive.c

@@ -148,6 +148,12 @@ static apr_status_t ad_setup_order(md_proto_driver_t *d, md_result_t *result, in
 /**************************************************************************************************/
 /* ACMEv2 renewal */
 
+/* A wait cut short by a shutdown is not a failed renewal, do not report it as one. */
+static void wait_failed(md_result_t *result, apr_status_t rv, const char *msg)
+{
+    md_result_set(result, rv, APR_STATUS_IS_EINTR(rv)? "Interrupted by shutdown" : msg);
+}
+
 apr_status_t md_acmev2_drive_renew(md_acme_driver_t *ad, md_proto_driver_t *d, md_result_t *result)
 {
     apr_status_t rv = APR_SUCCESS;
@@ -208,14 +214,14 @@ apr_status_t md_acmev2_drive_renew(md_acme_driver_t *ad, md_proto_driver_t *d, m
     rv = md_acme_order_monitor_authzs(ad->order, ad->acme, d->md,
                                       ad->authz_monitor_timeout, result, d->p);
     if (APR_SUCCESS != rv) {
-      md_result_set(result, rv, "Error waiting on domain names to be validated");
+      wait_failed(result, rv, "Error waiting on domain names to be validated");
       goto leave;
     }
 
     rv = md_acme_order_await_ready(ad->order, ad->acme, d->md,
                                    ad->authz_monitor_timeout, result, d->p);
     if (APR_SUCCESS != rv) {
-      md_result_set(result, rv, "Error waiting for order to become ready");
+      wait_failed(result, rv, "Error waiting for order to become ready");
       goto leave;
     }
 
@@ -228,7 +234,7 @@ apr_status_t md_acmev2_drive_renew(md_acme_driver_t *ad, md_proto_driver_t *d, m
     rv = md_acme_order_await_valid(ad->order, ad->acme, d->md, 
                                    ad->authz_monitor_timeout, result, d->p);
     if (APR_SUCCESS != rv) {
-      md_result_set(result, rv, "Error waiting for order to become valid.");
+      wait_failed(result, rv, "Error waiting for order to become valid.");
       goto leave;
     }
 

modules/md/md_result.c

@@ -210,6 +210,7 @@ void md_result_assign(md_result_t *dest, const md_result_t *src)
    dest->detail = src->detail;
    dest->activity = src->activity;
    dest->ready_at = src->ready_at;
+   dest->retry_at = src->retry_at;
    dest->subproblems = src->subproblems;
 }
 
@@ -220,6 +221,7 @@ void md_result_dup(md_result_t *dest, const md_result_t *src)
    dest->detail = src->detail? apr_pstrdup(dest->p, src->detail) : NULL; 
    dest->activity = src->activity? apr_pstrdup(dest->p, src->activity) : NULL; 
    dest->ready_at = src->ready_at;
+   dest->retry_at = src->retry_at;
    dest->subproblems = src->subproblems? md_json_clone(dest->p, src->subproblems) : NULL;
    on_change(dest);
 }

modules/md/md_result.h

@@ -35,6 +35,7 @@ struct md_result_t {
     const struct md_json_t *subproblems;
     const char *activity;
     apr_time_t ready_at;
+    apr_time_t retry_at;        /* earliest time the server asked us to come back, or 0 */
     md_result_change_cb *on_change;
     void *on_change_data;
     md_result_raise_cb *on_raise;

modules/md/md_status.c

@@ -680,10 +680,26 @@ void md_job_end_run(md_job_t *job, md_result_t *result)
         job->dirty = 1;
         md_job_log_append(job, "finished", NULL, NULL);
     }
+    else if (APR_STATUS_IS_EINTR(result->status)) {
+        /* Cancelled by a shutdown, not a failed run: no error is counted
+         * and no delay applies, the next process starts over. */
+        job->next_run = 0;
+        job->dirty = 1;
+    }
     else {
+        apr_time_t now = apr_time_now();
+        apr_time_t retry_at = result->retry_at;
+
         ++job->error_runs;
         job->dirty = 1;
-        job->next_run = apr_time_now() + md_job_delay_on_errors(job, job->error_runs, result->problem);
+        job->next_run = now + md_job_delay_on_errors(job, job->error_runs, result->problem);
+        /* honour a Retry-After of the CA, but not for longer than we ever back off */
+        if (retry_at > now + apr_time_from_sec(24*60*60)) {
+            retry_at = now + apr_time_from_sec(24*60*60);
+        }
+        if (retry_at > job->next_run) {
+            job->next_run = retry_at;
+        }
     }
     job_observation_end(job);
 }