diff --git a/acme/api/order.go b/acme/api/order.go index 0232092da..cb0d01a53 100644 --- a/acme/api/order.go +++ b/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 diff --git a/acme/api/order_test.go b/acme/api/order_test.go index 0fadcf06d..125410f2f 100644 --- a/acme/api/order_test.go +++ b/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"}) } diff --git a/acme/order.go b/acme/order.go index 0040aee16..400268876 100644 --- a/acme/order.go +++ b/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) { diff --git a/acme/order_test.go b/acme/order_test.go index cdcbdb518..9ea76f7aa 100644 --- a/acme/order_test.go +++ b/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", diff --git a/acme/status.go b/acme/status.go index d9aae82dc..fbe4cee5d 100644 --- a/acme/status.go +++ b/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" )