diff --git a/async.go b/async.go index a2391803..15cfe710 100644 --- a/async.go +++ b/async.go @@ -95,6 +95,88 @@ func (jm *jobManager) worker() { } } +// renewalBackoff tracks, per certificate name, when the next renewal +// attempt driven by the periodic maintenance loop is allowed to run. It +// exists so that queueRenewalTask can make a single renewal attempt per +// call (via renewCertOnce) instead of submitting a job to jm that loops +// internally through retryIntervals for up to maxRetryDuration -- which +// would otherwise occupy jm's dedup slot for that name and cause +// subsequent maintenance ticks to silently no-op via jm.Submit until the +// long-lived job's own internal sleep happens to wake up (up to 6 hours +// later). By moving the schedule here, the periodic maintenance tick +// (which already runs every RenewCheckInterval and only proceeds if the +// certificate still needs renewal) becomes the actual retry driver, while +// still following the same backoff schedule as doWithRetry. +type renewalBackoff struct { + mu sync.Mutex + state map[string]*renewalBackoffState +} + +type renewalBackoffState struct { + nextAttempt time.Time + intervalIdx int // -1 until the first failed attempt + firstAttempt time.Time +} + +var renewalRetrySchedule = &renewalBackoff{} + +// readyFor reports whether name is currently allowed to attempt a renewal. +// It is always true for a name with no recorded failure. +func (rb *renewalBackoff) readyFor(name string) bool { + return rb.readyForAsOf(name, time.Now()) +} + +// readyForAsOf is like readyFor but evaluates readiness as of the given +// time instead of time.Now(); it exists so tests can exercise the backoff +// schedule without sleeping for real minutes/hours/days. +func (rb *renewalBackoff) readyForAsOf(name string, asOf time.Time) bool { + rb.mu.Lock() + defer rb.mu.Unlock() + st, ok := rb.state[name] + if !ok { + return true + } + return !asOf.Before(st.nextAttempt) +} + +// recordFailure schedules the next allowed attempt for name using the same +// retryIntervals/maxRetryDuration schedule as doWithRetry. It reports +// whether the overall retry budget (maxRetryDuration since the first +// recorded failure in this cycle) has been exhausted. If exhausted, the +// backoff cycle for name is reset (mirroring doWithRetry's own behavior of +// giving up and returning), so the next maintenance tick will attempt +// immediately rather than being throttled forever; if the certificate still +// needs renewal by then, a fresh backoff cycle begins. +func (rb *renewalBackoff) recordFailure(name string, now time.Time) (exhausted bool) { + rb.mu.Lock() + defer rb.mu.Unlock() + if rb.state == nil { + rb.state = make(map[string]*renewalBackoffState) + } + st, ok := rb.state[name] + if !ok { + st = &renewalBackoffState{intervalIdx: -1, firstAttempt: now} + rb.state[name] = st + } + if now.Sub(st.firstAttempt) >= maxRetryDuration { + delete(rb.state, name) + return true + } + if st.intervalIdx < len(retryIntervals)-1 { + st.intervalIdx++ + } + st.nextAttempt = now.Add(retryIntervals[st.intervalIdx]) + return false +} + +// clear forgets any recorded backoff state for name, e.g. after a +// successful renewal or once the certificate no longer needs renewing. +func (rb *renewalBackoff) clear(name string) { + rb.mu.Lock() + defer rb.mu.Unlock() + delete(rb.state, name) +} + func doWithRetry(ctx context.Context, log *zap.Logger, f func(context.Context) error) error { var attempts int ctx = context.WithValue(ctx, AttemptsCtxKey, &attempts) diff --git a/async_test.go b/async_test.go index a118733e..71c10c42 100644 --- a/async_test.go +++ b/async_test.go @@ -69,3 +69,84 @@ func waitUntil(timeout time.Duration, cond func() bool) bool { } return cond() } + +// TestRenewalBackoffSchedule verifies the scheduling primitive that lets +// queueRenewalTask pace retries itself instead of relying on a single +// long-lived jm job sleeping between attempts (see caddyserver/caddy#7843: +// after a transient DNS outage cleared, renewal did not happen again until +// the process was restarted, because the in-flight job's own multi-hour +// internal sleep -- not the periodic maintenance tick -- was governing +// retries, and jm.Submit silently dropped every duplicate submission from +// the maintenance tick in the meantime). +// +// It uses a fresh *renewalBackoff (not the shared package-level +// renewalRetrySchedule) and a synthetic clock so it doesn't need to sleep +// for real minutes/hours/days. +func TestRenewalBackoffSchedule(t *testing.T) { + rb := &renewalBackoff{} + const name = "renew_example.com" + now := time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC) + + // No recorded failures yet: always ready. + if !rb.readyFor(name) { + t.Fatal("expected a name with no recorded failure to be ready immediately") + } + + // First failure: schedules the first retry interval out. + if exhausted := rb.recordFailure(name, now); exhausted { + t.Fatal("did not expect the retry budget to be exhausted after a single failure") + } + if rb.readyForAsOf(name, now) { + t.Fatal("expected name to not be ready for a retry immediately after recording a failure") + } + + // Not ready right up until (but not including) the first retry interval. + almostThere := now.Add(retryIntervals[0] - time.Millisecond) + if rb.readyForAsOf(name, almostThere) { + t.Fatal("expected name to still not be ready just before its scheduled retry time") + } + + // Ready once the first retry interval has elapsed. + dueTime := now.Add(retryIntervals[0]) + if !rb.readyForAsOf(name, dueTime) { + t.Fatal("expected name to be ready once its scheduled retry time has passed") + } + + // A second consecutive failure advances to the next (longer) interval, + // counted from when this second attempt happened. + if exhausted := rb.recordFailure(name, dueTime); exhausted { + t.Fatal("did not expect the retry budget to be exhausted after a second failure") + } + secondDue := dueTime.Add(retryIntervals[1]) + if rb.readyForAsOf(name, secondDue.Add(-time.Millisecond)) { + t.Fatal("expected name to still be backing off before the second scheduled retry time") + } + if !rb.readyForAsOf(name, secondDue) { + t.Fatal("expected name to be ready once the second scheduled retry time has passed") + } + + // clear() makes the name immediately ready again, as happens after a + // successful renewal. + rb.recordFailure(name, secondDue) + if rb.readyForAsOf(name, secondDue) { + t.Fatal("expected name to be backing off before calling clear") + } + rb.clear(name) + if !rb.readyForAsOf(name, secondDue) { + t.Fatal("expected name to be immediately ready after clear") + } + + // Once the cumulative failure window reaches maxRetryDuration, the + // caller is told the budget is exhausted and the schedule resets, so a + // fresh maintenance tick is not throttled indefinitely (mirroring + // doWithRetry's own give-up-and-return behavior). + start := now + rb.recordFailure(name, start) + exhausted := rb.recordFailure(name, start.Add(maxRetryDuration)) + if !exhausted { + t.Fatal("expected the retry budget to be reported exhausted once maxRetryDuration has elapsed") + } + if !rb.readyForAsOf(name, start.Add(maxRetryDuration)) { + t.Fatal("expected name to be immediately ready again after the retry budget was exhausted") + } +} diff --git a/config.go b/config.go index 27c39cd8..9c637655 100644 --- a/config.go +++ b/config.go @@ -807,16 +807,32 @@ func (cfg *Config) storageHasCertResourcesAnyIssuer(ctx context.Context, name st // cache with the new certificate. The certificate will not be renewed if it // is not close to expiring unless force is true. func (cfg *Config) RenewCertSync(ctx context.Context, name string, force bool) error { - return cfg.renewCert(ctx, name, force, true) + return cfg.renewCert(ctx, name, force, false, true) } // RenewCertAsync is the same as RenewCertSync(), except it runs in the // background; i.e. non-interactively, and with retries if it fails. func (cfg *Config) RenewCertAsync(ctx context.Context, name string, force bool) error { - return cfg.renewCert(ctx, name, force, false) + return cfg.renewCert(ctx, name, force, true, false) } -func (cfg *Config) renewCert(ctx context.Context, name string, force, interactive bool) error { +// renewCertOnce makes a single, non-interactive renewal attempt for name and +// returns whatever error results, without looping through the retryIntervals +// schedule internally. Unlike RenewCertSync, it never prompts on stdin +// (interactive is always false for PreCheck/setEmail purposes), so it is safe +// to call from a background goroutine. It still acquires/releases the same +// storage lock as RenewCertSync/RenewCertAsync around the single attempt, so +// cross-instance coordination is preserved. +// +// This exists for callers, such as the periodic maintenance loop, that +// already have their own outer retry/backoff driver and therefore don't want +// a single renewal job to camp on the jobManager dedup slot for its name for +// up to maxRetryDuration; see queueRenewalTask. +func (cfg *Config) renewCertOnce(ctx context.Context, name string, force bool) error { + return cfg.renewCert(ctx, name, force, false, false) +} + +func (cfg *Config) renewCert(ctx context.Context, name string, force, retry, interactive bool) error { if len(cfg.Issuers) == 0 { return fmt.Errorf("no issuers configured; impossible to renew or check existing certificate in storage") } @@ -1034,10 +1050,10 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv return nil } - if interactive { - err = f(ctx) - } else { + if retry { err = doWithRetry(ctx, log, f) + } else { + err = f(ctx) } return err diff --git a/maintain.go b/maintain.go index bda4a93f..6c9a68e8 100644 --- a/maintain.go +++ b/maintain.go @@ -229,25 +229,46 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error { func (certCache *Cache) queueRenewalTask(ctx context.Context, oldCert Certificate, cfg *Config) error { log := certCache.logger.Named("maintenance") - timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC()) - log.Info("certificate expires soon; queuing for renewal", - zap.Strings("identifiers", oldCert.Names), - zap.Duration("remaining", timeLeft)) - // Get the name which we should use to renew this certificate; // we only support managing certificates with one name per cert, // so this should be easy. renewName := oldCert.Names[0] + jobName := "renew_" + renewName + + // If a previous attempt for this name failed, don't try again until the + // backoff schedule (the same retryIntervals used by doWithRetry) says + // we're allowed to. This is what actually paces retries now: each + // renewal job below makes just ONE attempt and returns, so it never + // occupies jm's dedup slot for longer than a single attempt takes. + // Without this check, a certificate that keeps needing renewal (e.g. + // because the underlying cause, like a DNS outage, hasn't cleared yet) + // would cause a new attempt on every single maintenance tick, which is + // exactly the hammering that retryIntervals exists to avoid. + if !renewalRetrySchedule.readyFor(jobName) { + log.Debug("certificate expires soon, but renewal already failed recently; waiting for backoff before retrying", + zap.Strings("identifiers", oldCert.Names)) + return nil + } - // queue up this renewal job (is a no-op if already active or queued) - jm.Submit(cfg.Logger, "renew_"+renewName, func() error { + timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC()) + log.Info("certificate expires soon; queuing for renewal", + zap.Strings("identifiers", oldCert.Names), + zap.Duration("remaining", timeLeft)) + + // Queue up this renewal job (is a no-op if already active or queued, + // e.g. because this same certificate was independently queued for + // renewal elsewhere, such as manageOne or an on-demand handshake). + // Since this job makes only a single attempt (renewCertOnce) instead of + // looping internally for up to maxRetryDuration, it will not block + // future maintenance ticks from making progress once it returns. + jm.Submit(cfg.Logger, jobName, func() error { timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC()) log.Info("attempting certificate renewal", zap.Strings("identifiers", oldCert.Names), zap.Duration("remaining", timeLeft)) // perform renewal - crucially, this happens OUTSIDE a lock on certCache - err := cfg.RenewCertAsync(ctx, renewName, false) + err := cfg.renewCertOnce(ctx, renewName, false) if err != nil { if cfg.OnDemand != nil { // loaded dynamically, remove dynamically @@ -255,8 +276,14 @@ func (certCache *Cache) queueRenewalTask(ctx context.Context, oldCert Certificat certCache.removeCertificate(oldCert) certCache.mu.Unlock() } + if exhausted := renewalRetrySchedule.recordFailure(jobName, time.Now()); exhausted { + log.Error("final attempt; giving up until next scheduled renewal check finds the certificate still needs renewal", + zap.Strings("identifiers", oldCert.Names), + zap.Error(err)) + } return fmt.Errorf("%v %v", oldCert.Names, err) } + renewalRetrySchedule.clear(jobName) // successful renewal, so update in-memory cache by loading // renewed certificate so it will be used with handshakes diff --git a/maintain_test.go b/maintain_test.go new file mode 100644 index 00000000..36c38487 --- /dev/null +++ b/maintain_test.go @@ -0,0 +1,160 @@ +package certmagic + +import ( + "context" + "crypto/x509" + "crypto/x509/pkix" + "fmt" + "math/big" + "sync/atomic" + "testing" + "time" +) + +// failingIssuer is a fake Issuer that always fails, simulating a CA +// challenge validation failure (e.g. because DNS is broken, as in +// caddyserver/caddy#7843). It counts how many times Issue was called so +// tests can assert on attempt cadence. +type failingIssuer struct { + calls atomic.Int32 + err error +} + +func (fi *failingIssuer) Issue(ctx context.Context, csr *x509.CertificateRequest) (*IssuedCertificate, error) { + fi.calls.Add(1) + return nil, fi.err +} + +func (fi *failingIssuer) IssuerKey() string { return "failing_test_issuer" } + +// TestQueueRenewalTaskPacesRetriesItself is a regression test for +// caddyserver/caddy#7843: after a transient failure (e.g. a DNS outage) +// prevented renewal, the certificate did not get renewed again even after +// the underlying problem cleared, until the process was restarted. +// +// Root cause: queueRenewalTask used to submit a job to the package-level +// jm that internally looped through doWithRetry's retryIntervals schedule +// for up to maxRetryDuration (30 days) without returning. Because jm.Submit +// silently drops duplicate submissions for a name that is already +// in-flight, every subsequent periodic maintenance tick's call to +// queueRenewalTask for the same certificate was a silent no-op: the only +// thing actually driving retries was the single long-lived job's own +// internal sleep, which could be up to 6 hours between attempts, and, +// depending on scheduling, could appear to simply stop making progress. +// +// This test simulates two consecutive maintenance ticks in quick +// succession for a certificate whose issuer always fails, and asserts: +// 1. The first tick makes exactly one renewal attempt. +// 2. A second tick immediately afterward makes NO additional attempt, +// because we are intentionally backing off (this is desired -- we +// don't want to hammer the CA every RenewCheckInterval). +// 3. Once the backoff interval has elapsed, a third tick DOES make +// another attempt -- proving that renewal attempts are paced by an +// externally observable, bounded schedule (retryIntervals[0], on the +// order of a minute) rather than being silently stuck behind a +// multi-hour-or-longer sleep inside a single dedup-protected job. +func TestQueueRenewalTaskPacesRetriesItself(t *testing.T) { + const domain = "example.com" + issuer := &failingIssuer{err: fmt.Errorf("simulated DNS-01 challenge failure")} + + certCache := &Cache{ + cache: make(map[string]Certificate), + cacheIndex: make(map[string][]string), + logger: defaultTestLogger, + } + cfg := &Config{ + Issuers: []Issuer{issuer}, + Storage: &FileStorage{Path: t.TempDir()}, + Logger: defaultTestLogger, + DisableARI: true, // keep the renewal-needed check to plain expiration logic + ReusePrivateKeys: true, // avoid needing a KeySource for a fresh key + certCache: certCache, + } + cfg.OCSP.DisableStapling = true + + // Build an already-expired self-signed leaf certificate and stash it in + // storage as the "current" cert resource, so loadCertResourceAnyIssuer + // finds something to renew. + tmpl := &x509.Certificate{ + SerialNumber: big.NewInt(1), + Subject: pkix.Name{CommonName: domain}, + DNSNames: []string{domain}, + NotBefore: time.Now().Add(-60 * 24 * time.Hour), + NotAfter: time.Now().Add(-1 * time.Hour), // already expired + } + leaf, priv, certPEM := mustIssueTestCertificate(t, tmpl, nil, nil) + + privPEM, err := PEMEncodePrivateKey(priv) + if err != nil { + t.Fatalf("encoding private key: %v", err) + } + + certRes := CertificateResource{ + SANs: []string{domain}, + CertificatePEM: certPEM, + PrivateKeyPEM: privPEM, + issuerKey: issuer.IssuerKey(), + } + ctx := context.Background() + if err := cfg.saveCertResource(ctx, issuer, certRes); err != nil { + t.Fatalf("seeding cert resource in storage: %v", err) + } + + oldCert := Certificate{ + Names: []string{domain}, + managed: true, + issuerKey: issuer.IssuerKey(), + } + oldCert.Leaf = leaf + + jobName := "renew_" + domain + // Make sure we start from a clean slate in the shared package-level + // schedule, in case another test left state behind. + renewalRetrySchedule.clear(jobName) + t.Cleanup(func() { renewalRetrySchedule.clear(jobName) }) + + // --- Tick 1: should make exactly one attempt, then back off. --- + if err := certCache.queueRenewalTask(ctx, oldCert, cfg); err != nil { + t.Fatalf("queueRenewalTask (tick 1): %v", err) + } + if !waitUntil(time.Second, func() bool { return issuer.calls.Load() == 1 }) { + t.Fatalf("expected exactly 1 issuance attempt after tick 1, got %d", issuer.calls.Load()) + } + // Give the job's error-handling path (which calls + // renewalRetrySchedule.recordFailure) a moment to run after Issue + // returns, since it happens in the jobManager worker goroutine. + if !waitUntil(time.Second, func() bool { return !renewalRetrySchedule.readyFor(jobName) }) { + t.Fatal("expected renewal name to be backing off after a failed attempt") + } + + // --- Tick 2: fires immediately after tick 1; must NOT attempt again, + // because we are still within the first backoff interval. This is the + // crux of the fix: previously it was jm's dedup (silent, unbounded) + // doing this job; now it's an explicit, bounded backoff check. --- + if err := certCache.queueRenewalTask(ctx, oldCert, cfg); err != nil { + t.Fatalf("queueRenewalTask (tick 2): %v", err) + } + time.Sleep(50 * time.Millisecond) // give any (unwanted) job a chance to run + if got := issuer.calls.Load(); got != 1 { + t.Fatalf("expected still only 1 issuance attempt immediately after tick 2 (should be backing off), got %d", got) + } + + // --- Simulate the backoff interval elapsing by directly rewinding the + // recorded schedule (equivalent to waiting retryIntervals[0], which we + // don't want this test to actually spend real time on). --- + renewalRetrySchedule.mu.Lock() + if st, ok := renewalRetrySchedule.state[jobName]; ok { + st.nextAttempt = time.Now().Add(-time.Millisecond) + } else { + t.Fatal("expected backoff state to be recorded for job name") + } + renewalRetrySchedule.mu.Unlock() + + // --- Tick 3: backoff has elapsed, so this tick must retry. --- + if err := certCache.queueRenewalTask(ctx, oldCert, cfg); err != nil { + t.Fatalf("queueRenewalTask (tick 3): %v", err) + } + if !waitUntil(time.Second, func() bool { return issuer.calls.Load() == 2 }) { + t.Fatalf("expected a second issuance attempt once the backoff interval elapsed, got %d", issuer.calls.Load()) + } +}