feat(auth): name the path that granted access, and stop blaming the caller

Closes #1. Closes gitea-mcp#58. Closes gitea-mcp#60.

Three small changes to one decision point, kept together because they are the
same surface and the same incident.

1. A JWT IS NEVER A STATIC-TOKEN MISMATCH (gitea-mcp#58)

The fall-through reason was chosen by which comparison ran last, not by what the
caller presented. So a JWT against a server with no JWT auth configured logged:

    reason=static_token_mismatch  token_type=jwt  status=401

The two fields contradict each other, and the sentence reads as "you presented
the wrong token" when the truth is "this server could not have accepted any
token of that kind". The misdirection reached the user — claude.ai surfaces
"Authorization with gitea failed. You can check your credentials and
permissions." — and a debugging session went into re-running the OAuth flow
while the credentials were valid throughout.

Now `jwt_auth_not_configured` for a JWT; `static_token_mismatch` stays, and is
asserted to stay, for an actual static-token mismatch. Fixing the misleading
case must not delete the accurate one.

Note this is now the ONLY way to reach that branch with a JWT: since v0.6.0 a
validator that merely could not reach its issuer is non-nil and answers
ErrUnavailable -> 503. A nil validator means the server was never given an
issuer.

2. SUCCESS IS LOGGED, WITH THE PATH THAT GRANTED IT (gitea-mcp#60)

The middleware logged only on rejection. After re-authing a connector there was
no way to tell whether a request used the static token or a JWT, only inference
from which failures were absent. A log that proves a request failed, and nothing
about how the successful ones succeeded, cannot answer the question anyone
actually has during an auth incident.

    INFO mcp auth accepted auth_path=jwt caller=alice token_fp=... remote=...
    INFO mcp auth accepted auth_path=static token_fp=... remote=...

Same disclosure rules as deny: a fingerprint, never the credential. The JWT
subject is included because distinguishing WHO is the point of that path;
`caller` is omitted rather than empty for the static path, which has no identity
to report.

3. JWKS REFRESH INTERVAL IS CONFIGURABLE (#1)

It was hardcoded at 1h, so an issuer rotating its signing key could leave every
consumer rejecting valid JWTs for up to an hour. WithRefreshInterval, defaulting
to 1h so nothing changes for existing callers.

Variadic, per #1's own preferred option — a new positional parameter would force
a coordinated bump across every consumer. Deliberately NOT read from the
environment inside the library: a shared lib calling os.Getenv is a hidden
dependency that surprises its consumers. Config ownership stays at the edge.

The effective value is logged when an issuer resolves, which is #1's second
acceptance criterion and the thing an operator needs during a key-rotation
incident. The test asserts the configured value reaches the registration site
via that line — a silently-ignored option being the failure mode worth pinning.
Whether jwx then honours it is jwx's to test.

One of my own assertions was wrong and the test caught it: tokenType() says
"opaque", not "static", for a non-JWT credential. Corrected to the existing
vocabulary rather than changing the vocabulary to match a new test.

Verified: golangci-lint 0 issues; go vet clean; go test -race -count=1 ok.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

auth/bearer.go

@@ -56,14 +56,16 @@ func BearerMiddleware(
 		// 1. Static Bearer wins first — never emits a challenge.
 		if staticToken != "" &&
 			subtle.ConstantTimeCompare([]byte(rawToken), []byte(staticToken)) == 1 {
+			accept(r, "static", "", rawToken)
 			next.ServeHTTP(w, r)
 			return
 		}
 
 		// 2. Then Dex JWT, if configured.
 		if validator != nil {
-			switch _, err := validator.Validate(r.Context(), rawToken); {
+			switch sub, err := validator.Validate(r.Context(), rawToken); {
 			case err == nil:
+				accept(r, "jwt", sub, rawToken)
 				next.ServeHTTP(w, r)
 				return
 			case errors.Is(err, ErrUnavailable):
@@ -78,11 +80,46 @@ func BearerMiddleware(
 			}
 		}
 
-		// 3. Static token was wrong and no JWT validator is configured.
+		// 3. Nothing matched. Which reason depends on what was PRESENTED, not on
-		deny(w, r, realm, resourceMetadataURL, http.StatusUnauthorized, "static_token_mismatch", rawToken)
+		// which comparison happened to run last (gitea-mcp#58).
+		//
+		// `static_token_mismatch` for a JWT reads as "the caller presented the
+		// wrong token" when the truth is "this server has no JWT auth
+		// configured, so a correct token had no chance". The misdirection
+		// reached the user — claude.ai surfaced "check your credentials" while
+		// the credentials were valid — and a debugging session went into
+		// re-running the OAuth flow before anyone read the log.
+		reason := "static_token_mismatch"
+		if tokenType(rawToken) == "jwt" {
+			reason = "jwt_auth_not_configured"
+		}
+		deny(w, r, realm, resourceMetadataURL, http.StatusUnauthorized, reason, rawToken)
 	})
 }
 
+// accept audit-logs a SUCCESSFUL authentication, naming the path that granted it
+// (gitea-mcp#60).
+//
+// The middleware used to log only on rejection, so after re-authing a connector
+// there was no way to tell whether a request had used the static token or a JWT
+// — only inference from which failures were absent. A log that can prove a
+// request failed, and nothing about how the successful ones succeeded, cannot
+// answer the question anyone actually has during an auth incident.
+//
+// Same disclosure rules as deny: a fingerprint, never the credential.
+func accept(r *http.Request, authPath, caller, rawToken string) {
+	attrs := []any{
+		"auth_path", authPath,
+		"remote", clientIP(r),
+		"token_fp", fingerprint(rawToken),
+		"path", r.URL.Path,
+	}
+	if caller != "" {
+		attrs = append(attrs, "caller", caller)
+	}
+	slog.Info("mcp auth accepted", attrs...)
+}
+
 // deny writes the auth rejection and emits a structured audit log line
 // (gitea-mcp#9). The log records the reason, client IP, presented token type,
 // and a non-reversible token fingerprint — never the raw token, so nothing

auth/bearer_logging_test.go

@@ -0,0 +1,156 @@
+package auth
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+// captureLogs swaps the default logger for one writing JSON to a buffer, and
+// returns a decoder for the lines it collected. Matches the existing pattern in
+// TestBearerMiddleware_AuditLogsRejection.
+func captureLogs(t *testing.T) func() []map[string]any {
+	t.Helper()
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo})))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+
+	return func() []map[string]any {
+		var out []map[string]any
+		for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
+			if line == "" {
+				continue
+			}
+			var m map[string]any
+			require.NoError(t, json.Unmarshal([]byte(line), &m))
+			out = append(out, m)
+		}
+		return out
+	}
+}
+
+func call(h http.Handler, authz string) *httptest.ResponseRecorder {
+	req := httptest.NewRequest(http.MethodGet, "/mcp", nil)
+	if authz != "" {
+		req.Header.Set("Authorization", authz)
+	}
+	rec := httptest.NewRecorder()
+	h.ServeHTTP(rec, req)
+	return rec
+}
+
+// A well-formed JWT looks like this to tokenType(): three dotted segments. The
+// content does not matter — nothing parses it on the paths under test.
+const jwtShaped = "eyJhbGciOiJSUzI1NiJ9.eyJzdWIiOiJhbGljZSJ9.c2ln"
+
+// gitea-mcp#58: a JWT must never be rejected with a STATIC-token reason.
+//
+// The log said:
+//
+//	reason=static_token_mismatch  token_type=jwt  status=401
+//
+// which reads as "the caller presented the wrong token" when the truth was "this
+// server has no JWT auth configured, so a correct token had no chance". The
+// fields contradict each other and the misdirection reached the user: claude.ai
+// surfaced "Authorization with gitea failed. You can check your credentials and
+// permissions." The credentials were valid; a session went into re-running the
+// OAuth flow before anyone read the server log.
+func TestBearerMiddleware_JWTAgainstStaticOnlyServer_IsNotAStaticMismatch(t *testing.T) {
+	logs := captureLogs(t)
+	h := BearerMiddleware("the-static-token", nil, "gitea", "",
+		http.HandlerFunc(func(http.ResponseWriter, *http.Request) { t.Fatal("must not reach next") }))
+
+	rec := call(h, "Bearer "+jwtShaped)
+	require.Equal(t, http.StatusUnauthorized, rec.Code)
+
+	lines := logs()
+	require.Len(t, lines, 1)
+	require.Equal(t, "jwt", lines[0]["token_type"])
+	require.NotEqual(t, "static_token_mismatch", lines[0]["reason"],
+		"a JWT path must never report a static-token failure")
+	require.Equal(t, "jwt_auth_not_configured", lines[0]["reason"])
+}
+
+// The other half of the same claim: static_token_mismatch must still be reported
+// for an actual static-token mismatch. Fixing the misleading case must not
+// remove the accurate one.
+func TestBearerMiddleware_WrongOpaqueToken_IsStillAStaticMismatch(t *testing.T) {
+	logs := captureLogs(t)
+	h := BearerMiddleware("the-static-token", nil, "gitea", "",
+		http.HandlerFunc(func(http.ResponseWriter, *http.Request) { t.Fatal("must not reach next") }))
+
+	rec := call(h, "Bearer definitely-not-it")
+	require.Equal(t, http.StatusUnauthorized, rec.Code)
+
+	lines := logs()
+	require.Len(t, lines, 1)
+	// "opaque" is tokenType()'s existing word for a non-JWT credential; the
+	// point is only that it is NOT "jwt".
+	require.Equal(t, "opaque", lines[0]["token_type"])
+	require.Equal(t, "static_token_mismatch", lines[0]["reason"])
+}
+
+// gitea-mcp#60: the auth path is silent on success.
+//
+// After re-authing the claude.ai connector there was no way to tell from the
+// logs whether a request had used the static token or a JWT — only inference.
+// A middleware that logs solely on rejection can prove a request failed and
+// nothing about how the ones that worked, worked.
+func TestBearerMiddleware_LogsTheAcceptedPath(t *testing.T) {
+	t.Run("static", func(t *testing.T) {
+		logs := captureLogs(t)
+		reached := false
+		h := BearerMiddleware("the-static-token", nil, "gitea", "",
+			http.HandlerFunc(func(http.ResponseWriter, *http.Request) { reached = true }))
+
+		require.Equal(t, http.StatusOK, call(h, "Bearer the-static-token").Code)
+		require.True(t, reached)
+
+		lines := logs()
+		require.Len(t, lines, 1, "a successful auth must leave exactly one line")
+		require.Equal(t, "mcp auth accepted", lines[0]["msg"])
+		require.Equal(t, "static", lines[0]["auth_path"])
+		require.NotEmpty(t, lines[0]["token_fp"])
+		require.NotContains(t, lines[0], "token", "the raw token must never be logged")
+	})
+
+	t.Run("jwt", func(t *testing.T) {
+		iss := newTestIssuer(t)
+		v, err := NewMultiJWTValidator(t.Context(),
+			[]IssuerConfig{{IssuerURL: iss.url, Audience: "aud"}})
+		require.NoError(t, err)
+
+		logs := captureLogs(t)
+		h := BearerMiddleware("the-static-token", v, "gitea", "",
+			http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}))
+
+		require.Equal(t, http.StatusOK, call(h, "Bearer "+iss.mint(t, "aud", "alice")).Code)
+
+		lines := logs()
+		require.Len(t, lines, 1)
+		require.Equal(t, "mcp auth accepted", lines[0]["msg"])
+		require.Equal(t, "jwt", lines[0]["auth_path"])
+		require.Equal(t, "alice", lines[0]["caller"],
+			"the JWT subject is the whole reason to distinguish this path")
+	})
+}
+
+// The fingerprint is what makes a log line correlatable across requests without
+// being a credential. It must be stable for one token and different for another,
+// and it must never be a prefix of the token itself.
+func TestFingerprint_StableAndNotDerivableBackToTheToken(t *testing.T) {
+	a := fingerprint("token-one")
+	b := fingerprint("token-two")
+
+	require.Equal(t, a, fingerprint("token-one"), "same token, same fingerprint")
+	require.NotEqual(t, a, b)
+	require.NotContains(t, "token-one", a)
+	require.False(t, strings.HasPrefix("token-one", a))
+}

auth/jwt.go

@@ -18,6 +18,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"sync"
 	"time"
@@ -115,6 +116,14 @@ func (e *issuerEntry) resolve(ctx context.Context, cache *jwk.Cache, retryInterv
 	}
 
 	e.jwksURI, e.lastErr = jwksURI, nil
+	// Stated, not assumed. An option that is silently ignored is worse than one
+	// that does not exist, and the effective interval is the thing an operator
+	// needs during a key-rotation incident.
+	slog.Info("jwt issuer resolved",
+		"issuer", e.issuer,
+		"jwks_uri", jwksURI,
+		"jwks_refresh_interval", refreshInterval.String(),
+	)
 	return jwksURI, nil
 }
 
@@ -144,6 +153,18 @@ func WithRetryInterval(d time.Duration) Option {
 	return func(o *options) { o.retryInterval = d }
 }
 
+// WithRefreshInterval sets the JWKS cache's minimum refresh interval
+// (mcp-chassis#1). It was hardcoded at 1h, so an issuer rotating its signing key
+// could leave every consumer rejecting valid JWTs for up to an hour.
+//
+// Variadic rather than a new positional parameter, and deliberately not read
+// from the process environment: a shared library reaching into os.Getenv is a
+// hidden dependency that surprises consumers. Config ownership stays at the
+// edge — the server parses its own env and passes the option.
+func WithRefreshInterval(d time.Duration) Option {
+	return func(o *options) { o.refreshInterval = d }
+}
+
 // JWTValidator validates Bearer JWTs against one or more trusted OIDC issuers.
 //
 // A nil *JWTValidator behaves as "JWT auth disabled" — Validate returns an

auth/jwt_bootrace_test.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/require"
 )
@@ -113,3 +114,42 @@ func TestJWTValidator_UnresolvableIssuer_IsUnavailableAndNotReady(t *testing.T)
 	require.False(t, ready)
 	require.Error(t, why)
 }
+
+// mcp-chassis#1: the JWKS min-refresh interval was hardcoded at 1h, so a signing
+// key rotation could leave every consumer rejecting valid JWTs for up to an hour.
+//
+// The interval reaching jwx's cache is not observable from outside jwx, and
+// testing jwx's own refresh behaviour is jwx's job. What IS this package's job,
+// and what this asserts, is that the configured value reaches the registration
+// site and is stated in the log — which is also #1's second acceptance criterion
+// ("effective value logged at init"). A silently-ignored option is the failure
+// mode worth pinning.
+func TestWithRefreshInterval_ReachesRegistrationAndIsLogged(t *testing.T) {
+	for _, tc := range []struct {
+		name string
+		opts []Option
+		want string
+	}{
+		{name: "default is 1h, unchanged", want: "1h0m0s"},
+		{name: "override", opts: []Option{WithRefreshInterval(5 * time.Minute)}, want: "5m0s"},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			iss := newTestIssuer(t)
+			logs := captureLogs(t)
+
+			v, err := NewMultiJWTValidator(t.Context(),
+				[]IssuerConfig{{IssuerURL: iss.url, Audience: "aud"}}, tc.opts...)
+			require.NoError(t, err)
+			require.NotNil(t, v)
+
+			var found bool
+			for _, l := range logs() {
+				if l["msg"] == "jwt issuer resolved" {
+					require.Equal(t, tc.want, l["jwks_refresh_interval"])
+					found = true
+				}
+			}
+			require.True(t, found, "resolving an issuer must state the effective refresh interval")
+		})
+	}
+}