* Implement RFC 8555 async order finalization to fix read timeout issue

RFC 8555 Section 7.4 explicitly defines "processing" as a distinct order state to decouple the finalize request (submit CSR) from certificate issuance (CA signing). This async handoff lets ACME servers back slow CAs without blocking the client. Current ACME implementation in step-ca skips this state which causes issues when an external CA sometimes takes a long time to return a signed certificate.

With this change, FinalizeOrder now immediately returns status=processing with Retry-After instead of blocking until the external CA responds. This prevents certbot's 45s & cert-manager's 60s default read timeout from firing when certificate signing takes longer. Certbot's poll_finalization loop handles the processing state natively.

 esnet/acme-proxy#22
 smallstep#2636

Author: netops2devops

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"
 )