Implement RFC 8555 async order finalization to fix read timeout issue with some ACME clients

acme/api/order.go

@@ -6,6 +6,7 @@ import (
 	"encoding/base64"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net"
 	"net/http"
 	"strings"
@@ -481,15 +482,53 @@ func FinalizeOrder(w http.ResponseWriter, r *http.Request) {
 	}
 
 	ca := mustAuthority(ctx)
-	if err = o.Finalize(ctx, db, fr.csr, ca, prov); err != nil {
-		render.Error(w, r, acme.WrapErrorISE(err, "error finalizing order"))
+
+	// Validate the order is ready without signing yet.
+	if err = o.UpdateStatus(ctx, db); err != nil {
+		render.Error(w, r, acme.WrapErrorISE(err, "error updating order status"))
+		return
+	}
+	if o.Status != acme.StatusReady {
+		render.Error(w, r, acme.NewError(acme.ErrorOrderNotReadyType, "order %s is not ready", o.ID))
 		return
 	}
 
+	// Immediately mark as processing and return — RFC 8555 §7.4 async finalization.
+	// This prevents ACME clients with short read timeouts (e.g. certbot's hardcoded
+	// 45s DEFAULT_NETWORK_TIMEOUT) from timing out while a slow external CA signs.
+	o.Status = acme.StatusProcessing
+	if err = db.UpdateOrder(ctx, o); err != nil {
+		render.Error(w, r, acme.WrapErrorISE(err, "error setting order to processing"))
+		return
+	}
 	linker.LinkOrder(ctx, o)
-
 	w.Header().Set("Location", linker.GetLink(ctx, acme.OrderLinkType, o.ID))
+	w.Header().Set("Retry-After", "15")
 	render.JSON(w, r, o)
+
+	// Sign the certificate in the background. DB status drives client polling responses.
+	// We capture orderID and csr rather than the order pointer to avoid data races with
+	// the HTTP response still being flushed.
+	orderID, csr := o.ID, fr.csr
+	go func() {
+		bgCtx := context.Background()
+		// Re-fetch from DB to get a clean copy, then reset to ready so
+		// Finalize()'s internal switch statement can proceed normally.
+		bgOrder, err := db.GetOrder(bgCtx, orderID)
+		if err != nil {
+			slog.Error("async finalization: failed to re-fetch order", "order", orderID, "err", err)
+			return
+		}
+		bgOrder.Status = acme.StatusReady
+		if err := bgOrder.Finalize(bgCtx, db, csr, ca, prov); err != nil {
+			slog.Error("async finalization failed", "order", orderID, "err", err)
+			bgOrder.Status = acme.StatusInvalid
+			_ = db.UpdateOrder(bgCtx, bgOrder)
+			return
+		}
+		// On success, Finalize() sets StatusValid and calls db.UpdateOrder internally.
+		slog.Info("async finalization succeeded", "order", orderID)
+	}()
 }
 
 // challengeTypes determines the types of challenges that should be used

acme/api/order_test.go

@@ -2424,10 +2424,11 @@ func TestHandler_FinalizeOrder(t *testing.T) {
 	assert.FatalError(t, err)
 
 	type test struct {
-		db         acme.DB
-		ctx        context.Context
-		statusCode int
-		err        *acme.Error
+		db             acme.DB
+		ctx            context.Context
+		statusCode     int
+		err            *acme.Error
+		expectedStatus acme.Status // for success cases; empty means skip status assertion
 	}
 	var tests = map[string]func(t *testing.T) test{
 		"fail/no-account": func(t *testing.T) test {
@@ -2569,7 +2570,9 @@ func TestHandler_FinalizeOrder(t *testing.T) {
 				err:        acme.NewError(acme.ErrorUnauthorizedType, "provisioner id mismatch"),
 			}
 		},
-		"fail/order-finalize-error": func(t *testing.T) test {
+		// Tests that an expired ready order fails at UpdateStatus, which tries to
+	// write StatusInvalid to the DB and gets an error back.
+	"fail/update-status-error": func(t *testing.T) test {
 			acc := &acme.Account{ID: "accountID"}
 			ctx := acme.NewProvisionerContext(context.Background(), prov)
 			ctx = context.WithValue(ctx, accContextKey, acc)
@@ -2594,7 +2597,8 @@ func TestHandler_FinalizeOrder(t *testing.T) {
 				err:        acme.NewErrorISE("force"),
 			}
 		},
-		"ok": func(t *testing.T) test {
+		// Tests that a DB failure when writing the processing status returns 500.
+		"fail/db.UpdateOrder-processing-error": func(t *testing.T) test {
 			acc := &acme.Account{ID: "accountID"}
 			ctx := acme.NewProvisionerContext(context.Background(), prov)
 			ctx = context.WithValue(ctx, accContextKey, acc)
@@ -2604,30 +2608,66 @@ func TestHandler_FinalizeOrder(t *testing.T) {
 				db: &acme.MockDB{
 					MockGetOrder: func(ctx context.Context, id string) (*acme.Order, error) {
 						return &acme.Order{
-							ID:               "orderID",
-							AccountID:        "accountID",
-							ProvisionerID:    fmt.Sprintf("acme/%s", prov.GetName()),
-							ExpiresAt:        naf,
-							Status:           acme.StatusValid,
-							AuthorizationIDs: []string{"foo", "bar", "baz"},
-							NotBefore:        nbf,
-							NotAfter:         naf,
-							Identifiers: []acme.Identifier{
-								{
-									Type:  "dns",
-									Value: "example.com",
-								},
-								{
-									Type:  "dns",
-									Value: "*.smallstep.com",
-								},
-							},
-							CertificateID: "certID",
+							ID:            "orderID",
+							AccountID:     "accountID",
+							ProvisionerID: fmt.Sprintf("acme/%s", prov.GetName()),
+							ExpiresAt:     naf,
+							Status:        acme.StatusReady,
 						}, nil
 					},
+					MockUpdateOrder: func(ctx context.Context, o *acme.Order) error {
+						return acme.NewErrorISE("force")
+					},
 				},
 				ctx:        ctx,
-				statusCode: 200,
+				statusCode: 500,
+				err:        acme.NewErrorISE("force"),
+			}
+		},
+		// Tests the happy path: a ready order immediately returns processing + Retry-After,
+		// and the background goroutine is short-circuited by an error on re-fetch.
+		"ok": func(t *testing.T) test {
+			acc := &acme.Account{ID: "accountID"}
+			ctx := acme.NewProvisionerContext(context.Background(), prov)
+			ctx = context.WithValue(ctx, accContextKey, acc)
+			ctx = context.WithValue(ctx, payloadContextKey, &payloadInfo{value: payloadBytes})
+			ctx = context.WithValue(ctx, chi.RouteCtxKey, chiCtx)
+			// firstCall acts as a one-shot token: the HTTP handler consumes it,
+			// the background goroutine gets the default error path and exits early.
+			firstCall := make(chan struct{}, 1)
+			firstCall <- struct{}{}
+			return test{
+				db: &acme.MockDB{
+					MockGetOrder: func(ctx context.Context, id string) (*acme.Order, error) {
+						select {
+						case <-firstCall:
+							return &acme.Order{
+								ID:               "orderID",
+								AccountID:        "accountID",
+								ProvisionerID:    fmt.Sprintf("acme/%s", prov.GetName()),
+								ExpiresAt:        naf,
+								Status:           acme.StatusReady,
+								AuthorizationIDs: []string{"foo", "bar", "baz"},
+								NotBefore:        nbf,
+								NotAfter:         naf,
+								Identifiers: []acme.Identifier{
+									{Type: "dns", Value: "example.com"},
+									{Type: "dns", Value: "*.smallstep.com"},
+								},
+							}, nil
+						default:
+							// Second call is from the background goroutine; return an
+							// error to short-circuit it so it doesn't race with assertions.
+							return nil, acme.NewErrorISE("test: short-circuit goroutine")
+						}
+					},
+					MockUpdateOrder: func(ctx context.Context, o *acme.Order) error {
+						return nil
+					},
+				},
+				ctx:            ctx,
+				statusCode:     200,
+				expectedStatus: acme.StatusProcessing,
 			}
 		},
 	}
@@ -2656,13 +2696,15 @@ func TestHandler_FinalizeOrder(t *testing.T) {
 				assert.Equals(t, ae.Subproblems, tc.err.Subproblems)
 				assert.Equals(t, res.Header["Content-Type"], []string{"application/problem+json"})
 			} else {
-				expB, err := json.Marshal(o)
-				assert.FatalError(t, err)
-
 				ro := new(acme.Order)
-				assert.FatalError(t, json.Unmarshal(body, ro))
+				assert.FatalError(t, json.Unmarshal(bytes.TrimSpace(body), ro))
 
-				assert.Equals(t, bytes.TrimSpace(body), expB)
+				if tc.expectedStatus != "" {
+					assert.Equals(t, ro.Status, tc.expectedStatus)
+				}
+				if tc.expectedStatus == acme.StatusProcessing {
+					assert.Equals(t, res.Header["Retry-After"], []string{"15"})
+				}
 				assert.Equals(t, res.Header["Location"], []string{u})
 				assert.Equals(t, res.Header["Content-Type"], []string{"application/json"})
 			}

acme/order.go

@@ -82,6 +82,15 @@ func (o *Order) UpdateStatus(ctx context.Context, db DB) error {
 		return nil
 	case StatusValid:
 		return nil
+	case StatusProcessing:
+		// Check expiry so orphaned orders (e.g. from a server restart mid-goroutine)
+		// eventually transition to invalid rather than staying stuck forever.
+		if now.After(o.ExpiresAt) {
+			o.Status = StatusInvalid
+			o.Error = NewError(ErrorMalformedType, "order has expired")
+			break
+		}
+		return nil
 	case StatusReady:
 		// Check expiry
 		if now.After(o.ExpiresAt) {

acme/order_test.go

@@ -48,6 +48,55 @@ func TestOrder_UpdateStatus(t *testing.T) {
 				o: o,
 			}
 		},
+		"ok/already-processing": func(t *testing.T) test {
+			now := clock.Now()
+			o := &Order{
+				Status:    StatusProcessing,
+				ExpiresAt: now.Add(5 * time.Minute),
+			}
+			return test{
+				o: o,
+			}
+		},
+		"ok/processing-expired": func(t *testing.T) test {
+			now := clock.Now()
+			o := &Order{
+				ID:        "oID",
+				AccountID: "accID",
+				Status:    StatusProcessing,
+				ExpiresAt: now.Add(-5 * time.Minute),
+			}
+			return test{
+				o: o,
+				db: &MockDB{
+					MockUpdateOrder: func(ctx context.Context, updo *Order) error {
+						assert.Equals(t, updo.ID, o.ID)
+						assert.Equals(t, updo.AccountID, o.AccountID)
+						assert.Equals(t, updo.Status, StatusInvalid)
+						assert.Equals(t, updo.ExpiresAt, o.ExpiresAt)
+						return nil
+					},
+				},
+			}
+		},
+		"fail/processing-expired-db.UpdateOrder-error": func(t *testing.T) test {
+			now := clock.Now()
+			o := &Order{
+				ID:        "oID",
+				AccountID: "accID",
+				Status:    StatusProcessing,
+				ExpiresAt: now.Add(-5 * time.Minute),
+			}
+			return test{
+				o: o,
+				db: &MockDB{
+					MockUpdateOrder: func(ctx context.Context, updo *Order) error {
+						return errors.New("force")
+					},
+				},
+				err: NewErrorISE("error updating order: force"),
+			}
+		},
 		"fail/error-unexpected-status": func(t *testing.T) test {
 			o := &Order{
 				Status: "foo",

acme/status.go

@@ -14,7 +14,8 @@ var (
 	StatusDeactivated = Status("deactivated")
 	// StatusReady -- ready; e.g. for an Order that is ready to be finalized.
 	StatusReady = Status("ready")
-	//statusExpired     = "expired"
-	//statusActive      = "active"
-	//statusProcessing  = "processing"
+	// StatusProcessing -- processing; the certificate is being issued.
+	StatusProcessing = Status("processing")
+	//statusExpired = "expired"
+	//statusActive  = "active"
 )