diff --git a/auth/bearer.go b/auth/bearer.go index 8d6909a..85d0cac 100644 --- a/auth/bearer.go +++ b/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. - deny(w, r, realm, resourceMetadataURL, http.StatusUnauthorized, "static_token_mismatch", rawToken) + // 3. Nothing matched. Which reason depends on what was PRESENTED, not on + // 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 diff --git a/auth/bearer_logging_test.go b/auth/bearer_logging_test.go new file mode 100644 index 0000000..15e7fc3 --- /dev/null +++ b/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)) +} diff --git a/auth/jwt.go b/auth/jwt.go index f555a68..98390c9 100644 --- a/auth/jwt.go +++ b/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 diff --git a/auth/jwt_bootrace_test.go b/auth/jwt_bootrace_test.go index 754c913..5869b35 100644 --- a/auth/jwt_bootrace_test.go +++ b/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") + }) + } +}