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) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UAqi2hS2dhZoatqcWoYZQk
This commit is contained in:
Evan Jarrett
2026-09-02 12:44:48 -05:00
co-authored by Claude Opus 5
parent a4aedbd2c8
commit 27ce122db0
3 changed files with 87 additions and 5 deletions
+42 -1
View File
@@ -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)
}
+28
View File
@@ -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)
}
})
}
}
+17 -4
View File
@@ -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)
}