Reduce ACME challenge log noise (#396)

* Log missing ACME challenges at DEBUG

The "looking up info for HTTP challenge" logs can become very noisy
(they produced ~2M logs in 24 hours for us).

Requests can come from external ACME clients and pre-checks for
challenges not initiated by the server. So treat this case
(where no issuer has stored a matching token) as DEBUG to reduce
noise.

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

* Log canceled challenge lookups at DEBUG

A big chunk of the noisy "looking up info for HTTP challenge"
logs are "context canceled".

So also log these as DEBUG, but only do so when both the
lookup error and HTTP request context are canceled.

Author: danillouz

config.go

@@ -1161,6 +1161,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
@@ -1188,6 +1190,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,
@@ -1197,15 +1200,19 @@ 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) {
 			continue
 		}
-		return Challenge{}, false, fmt.Errorf("opening distributed challenge token file %s: %v", tokenKey, err)
+		return Challenge{}, false, fmt.Errorf("opening distributed challenge token file %s: %w", 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)

httphandlers.go

@@ -15,6 +15,8 @@
 package certmagic
 
 import (
+	"context"
+	"errors"
 	"fmt"
 	"net/http"
 	"net/url"
@@ -114,7 +116,14 @@ 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
+		switch {
+		case errors.Is(err, errNoACMEChallengeInfo):
+			log = am.Logger.Debug
+		case errors.Is(err, context.Canceled) && errors.Is(r.Context().Err(), context.Canceled):
+			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),

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,88 @@ func TestHTTPChallengeHandlerNoOp(t *testing.T) {
 		}
 	}
 }
+
+func TestHTTPChallengeLookupLogLevel(t *testing.T) {
+	tests := []struct {
+		name          string
+		storage       Storage
+		cancelRequest bool
+		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: "request canceled",
+			storage: loadResultStorage{
+				Storage: &memoryStorage{},
+				err:     context.Canceled,
+			},
+			cancelRequest: true,
+			wantLevel:     zap.DebugLevel,
+		},
+		{
+			name: "storage operation canceled",
+			storage: loadResultStorage{
+				Storage: &memoryStorage{},
+				err:     context.Canceled,
+			},
+			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 tt.cancelRequest {
+				ctx, cancel := context.WithCancel(req.Context())
+				cancel()
+				req = req.WithContext(ctx)
+			}
+			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)
+			}
+		})
+	}
+}