From 27ce122db02e9bf4626820246f4787adfdbb602d Mon Sep 17 00:00:00 2001 From: Evan Jarrett Date: Wed, 2 Sep 2026 12:44:48 -0500 Subject: [PATCH] auth: stop logging an unresolvable hold DID at ERROR A hold DID that can never resolve is a property of stored user data, not a fault on our side. The value comes from a user's own sailor profile defaultHold, so any account can choose the appview's ERROR volume, and nothing is cached on the failure path, so it re-logs on every request for that user. On production this was not a rounding error: two accounts pointing at did:web:localhost%3A8080 produced 2956 of 2958 ERROR lines over seven days, 99.9%. The genuine rate underneath was about two a day, which made level=ERROR useless as a signal or an alert threshold. Classify at the resolution boundary instead of string-matching prose. ErrHoldDIDPermanent marks a malformed identifier or a missing DID document; those log at DEBUG while everything an operator could act on stays at ERROR. didWebHostUnusable is conservative on purpose: it only claims the cases we are sure about (percent-encoded ports, bare IPs, localhost), so an unfamiliar failure stays loud rather than being quietly swallowed. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01UAqi2hS2dhZoatqcWoYZQk --- pkg/atproto/resolver.go | 43 +++++++++++++++++++++++++++++++++++- pkg/atproto/resolver_test.go | 28 +++++++++++++++++++++++ pkg/auth/hold_remote.go | 21 ++++++++++++++---- 3 files changed, 87 insertions(+), 5 deletions(-) diff --git a/pkg/atproto/resolver.go b/pkg/atproto/resolver.go index c36a4fa..03447e9 100644 --- a/pkg/atproto/resolver.go +++ b/pkg/atproto/resolver.go @@ -2,15 +2,50 @@ package atproto import ( "context" + "errors" "fmt" "io" + "net" "net/http" "strings" "time" + "github.com/bluesky-social/indigo/atproto/identity" "github.com/bluesky-social/indigo/atproto/syntax" ) +// ErrHoldDIDPermanent marks a hold-DID resolution failure that no retry can +// fix: a malformed identifier, or a DID whose document does not exist. It is a +// fact about stored data — typically a stale or hand-edited sailor profile +// defaultHold — rather than a fault on our side, so callers can log it quietly +// instead of at ERROR and avoid burying real faults. Transient failures (a PLC +// blip, a network error) deliberately do not carry it. +var ErrHoldDIDPermanent = errors.New("hold DID is not resolvable") + +// didWebHostUnusable reports whether a did:web identifier names something the +// identity directory can never resolve. The directory requires a plain +// hostname and rejects ports (percent-encoded as %3A), bare IPs, and +// localhost. Detecting those here, rather than string-matching the directory's +// error prose, is what lets ResolveHoldDIDToURL classify the failure as +// permanent. Conservative by design: anything not clearly hopeless is left to +// the transient path, so an unfamiliar failure still surfaces loudly. +func didWebHostUnusable(did string) bool { + host, ok := strings.CutPrefix(did, "did:web:") + if !ok { + return false + } + if i := strings.IndexByte(host, ':'); i != -1 { // path-qualified did:web + host = host[:i] + } + if strings.Contains(host, "%3A") || strings.Contains(host, "%3a") { + return true // a port survived encoding, e.g. localhost%3A8080 + } + if host == "" || host == "localhost" || strings.HasSuffix(host, ".localhost") { + return true + } + return net.ParseIP(host) != nil +} + // holdDIDResolveClient bounds the /.well-known/atproto-did fetch so an // unreachable or slow hold can't stall /auth/token (this resolution runs on the // hot gate + fetch path) past Docker's token-fetch timeout. It's a plain @@ -98,7 +133,7 @@ func ResolveHoldDIDToURL(ctx context.Context, did string) (string, error) { directory := GetDirectory() didParsed, err := syntax.ParseDID(did) if err != nil { - return "", fmt.Errorf("invalid hold DID %q: %w", did, err) + return "", fmt.Errorf("invalid hold DID %q: %w: %w", did, ErrHoldDIDPermanent, err) } ident, err := directory.LookupDID(ctx, didParsed) @@ -109,6 +144,12 @@ func ResolveHoldDIDToURL(ctx context.Context, did string) (string, error) { if testMode && strings.HasPrefix(did, "did:web:") { return DIDWebToURL(did), nil } + // A missing DID document or a structurally unusable did:web will fail + // identically on every retry, so mark it permanent and let callers pick + // a quieter log level. + if errors.Is(err, identity.ErrDIDNotFound) || didWebHostUnusable(did) { + return "", fmt.Errorf("failed to resolve hold DID %s: %w: %w", did, ErrHoldDIDPermanent, err) + } return "", fmt.Errorf("failed to resolve hold DID %s: %w", did, err) } diff --git a/pkg/atproto/resolver_test.go b/pkg/atproto/resolver_test.go index a5e59e8..7d4f881 100644 --- a/pkg/atproto/resolver_test.go +++ b/pkg/atproto/resolver_test.go @@ -665,3 +665,31 @@ func TestResolveHandleToDIDContextCancellation(t *testing.T) { t.Log("Expected error due to context cancellation, but got success (identifier may have been parsed without network)") } } + +// TestDIDWebHostUnusable pins the classification that decides whether a hold +// resolution failure is logged at DEBUG or ERROR. Getting this wrong in the +// permissive direction is the safe failure (a real fault stays loud); getting +// it wrong the other way buries genuine errors, which is what BUGS finding 21 +// was about. +func TestDIDWebHostUnusable(t *testing.T) { + tests := []struct { + name string + did string + want bool + }{ + {"port survives percent-encoding", "did:web:localhost%3A8080", true}, + {"lowercase percent-encoding", "did:web:localhost%3a8080", true}, + {"bare localhost", "did:web:localhost", true}, + {"IPv4 literal", "did:web:172.28.0.3", true}, + {"real hold hostname", "did:web:us-chi1.cove.seamark.dev", false}, + {"path-qualified did:web", "did:web:example.com:user:alice", false}, + {"did:plc is not did:web", "did:plc:wnbpdx4bn5uts5yd2o2g3gnm", false}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := didWebHostUnusable(tt.did); got != tt.want { + t.Errorf("didWebHostUnusable(%q) = %v, want %v", tt.did, got, tt.want) + } + }) + } +} diff --git a/pkg/auth/hold_remote.go b/pkg/auth/hold_remote.go index 187c650..c9c318d 100644 --- a/pkg/auth/hold_remote.go +++ b/pkg/auth/hold_remote.go @@ -131,10 +131,23 @@ func (a *RemoteHoldAuthorizer) GetCaptainRecord(ctx context.Context, holdDID str "error", err) return staleCached.CaptainRecord, nil } - slog.Error("Captain record fetch failed", - "holdDID", holdDID, - "denial_reason", "captain_record_fetch_failed", - "error", err) + // A hold DID that can never resolve is a property of stored user data + // (a stale or hand-edited sailor profile defaultHold), not a fault on + // our side, and nothing is cached on this path — so it re-logs on every + // single request for that user. Two such accounts once produced 99.9% + // of this service's ERROR lines. Keep ERROR for failures an operator + // could actually act on. + if errors.Is(err, atproto.ErrHoldDIDPermanent) { + slog.Debug("Captain record fetch skipped, hold DID cannot be resolved", + "holdDID", holdDID, + "denial_reason", "captain_record_fetch_failed", + "error", err) + } else { + slog.Error("Captain record fetch failed", + "holdDID", holdDID, + "denial_reason", "captain_record_fetch_failed", + "error", err) + } return nil, fmt.Errorf("failed to get captain record for %s: %w", holdDID, err) }