From 91f9aac13746a4003c44b68334efee4dcaa224b0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dani=C3=ABl=20Illouz?= Date: Sun, 12 Jul 2026 19:07:23 +0200 Subject: [PATCH] Log missing ACME challenges at DEBUG The "looking up info for HTTP challenge" logs are incredibly noisy: https://onenr.io/0Zw0aEpp3Rv They produced ~2M logs in the last 24 hours! As discussed here: https://framer-team.slack.com/archives/C06505JMQK0/p1741360219851809?thread_ts=1741345255.812599&cid=C06505JMQK0 Most requests come from external ACME clients and pre-checks for challenges FDS did not initiate. So treat the "expected" case, where no issuer has stored a matching token, as DEBUG. But note that actionable failures will remain visible: - Storage lookup failures: WARN - Empty or corrupt challenge data: WARN - Certificate issuance/renewal failures: visible via existing error logs So if FDS initiated a challenge whose token is unexpectedly gone, this request log becomes DEBUG. If that causes validation to fail, the issuance or renewal failure remains visible separately. Fixes https://github.com/framer/company/issues/32009 --- config.go | 9 ++++- httphandlers.go | 7 +++- httphandlers_test.go | 78 ++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 92 insertions(+), 2 deletions(-) diff --git a/config.go b/config.go index 8a5f5342..0cd8e46a 100644 --- a/config.go +++ b/config.go @@ -1162,6 +1162,8 @@ func (cfg *Config) TLSConfig() *tls.Config { } } +var errNoACMEChallengeInfo = errors.New("no active ACME challenge") + // getACMEChallengeInfo loads the challenge info from either the internal challenge memory // or the external storage (implying distributed solving). The second return value // indicates whether challenge info was loaded from external storage. If true, the @@ -1189,6 +1191,7 @@ func (cfg *Config) getACMEChallengeInfo(ctx context.Context, identifier string, var chalInfo acme.Challenge var chalInfoBytes []byte var tokenKey string + var challengeFound bool for _, issuer := range cfg.Issuers { ds := distributedSolver{ storage: cfg.Storage, @@ -1198,6 +1201,7 @@ func (cfg *Config) getACMEChallengeInfo(ctx context.Context, identifier string, var err error chalInfoBytes, err = cfg.Storage.Load(ctx, tokenKey) if err == nil { + challengeFound = true break } if errors.Is(err, fs.ErrNotExist) { @@ -1205,8 +1209,11 @@ func (cfg *Config) getACMEChallengeInfo(ctx context.Context, identifier string, } return Challenge{}, false, fmt.Errorf("opening distributed challenge token file %s: %v", tokenKey, err) } + if !challengeFound { + return Challenge{}, false, fmt.Errorf("%w: no information found to solve challenge for identifier: %s", errNoACMEChallengeInfo, identifier) + } if len(chalInfoBytes) == 0 { - return Challenge{}, false, fmt.Errorf("no information found to solve challenge for identifier: %s", identifier) + return Challenge{}, false, fmt.Errorf("decoding challenge token file %s: empty data", tokenKey) } err := json.Unmarshal(chalInfoBytes, &chalInfo) diff --git a/httphandlers.go b/httphandlers.go index 0e04fa48..6247eda3 100644 --- a/httphandlers.go +++ b/httphandlers.go @@ -15,6 +15,7 @@ package certmagic import ( + "errors" "fmt" "net/http" "net/url" @@ -114,7 +115,11 @@ func (am *ACMEIssuer) distributedHTTPChallengeSolver(w http.ResponseWriter, r *h } // couldn't get challenge info even with distributed solver - am.Logger.Warn("looking up info for HTTP challenge", + log := am.Logger.Warn + if errors.Is(err, errNoACMEChallengeInfo) { + log = am.Logger.Debug + } + log("looking up info for HTTP challenge", zap.String("uri", r.RequestURI), zap.String("identifier", host), zap.String("remote_addr", r.RemoteAddr), diff --git a/httphandlers_test.go b/httphandlers_test.go index 2447ea69..949d1d84 100644 --- a/httphandlers_test.go +++ b/httphandlers_test.go @@ -15,12 +15,28 @@ package certmagic import ( + "context" + "errors" "net/http" "net/http/httptest" "os" "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" ) +type loadResultStorage struct { + Storage + data []byte + err error +} + +func (s loadResultStorage) Load(context.Context, string) ([]byte, error) { + return s.data, s.err +} + func TestHTTPChallengeHandlerNoOp(t *testing.T) { am := &ACMEIssuer{CA: "https://example.com/acme/directory", Logger: defaultTestLogger} testConfig := &Config{ @@ -59,3 +75,65 @@ func TestHTTPChallengeHandlerNoOp(t *testing.T) { } } } + +func TestHTTPChallengeLookupLogLevel(t *testing.T) { + tests := []struct { + name string + storage Storage + wantLevel zapcore.Level + }{ + { + name: "no active challenge", + storage: &memoryStorage{}, + wantLevel: zap.DebugLevel, + }, + { + name: "empty challenge data", + storage: loadResultStorage{ + Storage: &memoryStorage{}, + data: []byte{}, + }, + wantLevel: zap.WarnLevel, + }, + { + name: "storage failure", + storage: loadResultStorage{ + Storage: &memoryStorage{}, + err: errors.New("storage unavailable"), + }, + wantLevel: zap.WarnLevel, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + core, logs := observer.New(zap.DebugLevel) + logger := zap.New(core) + am := &ACMEIssuer{ + CA: "https://example.com/acme/directory", + Logger: logger, + } + am.config = &Config{ + Issuers: []Issuer{am}, + Storage: tt.storage, + Logger: logger, + } + + req := httptest.NewRequest( + http.MethodGet, + "http://example.com/.well-known/acme-challenge/token", + nil, + ) + if am.HandleHTTPChallenge(httptest.NewRecorder(), req) { + t.Fatal("expected challenge request not to be handled") + } + + entries := logs.FilterMessage("looking up info for HTTP challenge").All() + if len(entries) != 1 { + t.Fatalf("expected one challenge lookup log, got %d", len(entries)) + } + if entries[0].Level != tt.wantLevel { + t.Fatalf("expected log level %s, got %s", tt.wantLevel, entries[0].Level) + } + }) + } +}