fix(ingestion): bump mcp-chassis to v0.7.1; log auth rejections; label refused REST requests by route (#181)

Closes #155

Reviewed by pr-gatekeeper: #181 (comment) (block, round 1) and re-review at e05a13a (approve).

Co-authored-by: Mathias <mthbqv@gmail.com>

ingestion/cmd/server/jwt_validator.go

@@ -2,24 +2,25 @@ package main
 
 import (
 	"context"
+	"fmt"
 	"log/slog"
 
 	chassisauth "git.d-ma.be/mathias/mcp-chassis/auth"
-
-	"github.com/mathiasbq/hyperguild/ingestion/internal/startupretry"
 )
 
-// buildJWTValidator runs OIDC discovery under policy, so a 502 from an auth
-// upstream that is not serving yet on a cold boot is retried instead of
-// exiting (#83). It honours ctx between attempts.
-func buildJWTValidator(
-	ctx context.Context, logger *slog.Logger, issuer, audience string, policy startupretry.Policy,
-) (*chassisauth.JWTValidator, error) {
-	return startupretry.Do(ctx, policy, func(ctx context.Context) (*chassisauth.JWTValidator, error) {
-		v, err := chassisauth.NewJWTValidator(ctx, issuer, audience)
-		if err != nil {
-			logger.Warn("oidc discovery not ready, retrying", "err", err)
-		}
-		return v, err
-	})
+// buildJWTValidator builds the JWT validator for issuer (nil when issuer is
+// empty: JWT auth disabled). Since mcp-chassis v0.7 construction no longer
+// fails when OIDC discovery does (mcp-chassis#4): the issuer resolves lazily,
+// and until it does a JWT is answered 503-and-retry, not 401. That replaces
+// #83's boot-time retry loop (hyperguild#155). An issuer still unresolved at
+// boot is logged, so a misconfigured issuer is visible rather than silent.
+func buildJWTValidator(ctx context.Context, logger *slog.Logger, issuer, audience string) (*chassisauth.JWTValidator, error) {
+	v, err := chassisauth.NewJWTValidator(ctx, issuer, audience)
+	if err != nil {
+		return nil, fmt.Errorf("build jwt validator: %w", err)
+	}
+	if ok, rerr := v.Ready(ctx); !ok {
+		logger.Warn("jwt issuer not resolved at boot; JWTs answer 503 until it is", "issuer", issuer, "err", rerr)
+	}
+	return v, nil
 }

ingestion/cmd/server/jwt_validator_test.go

@@ -1,6 +1,7 @@
 package main
 
 import (
+	"bytes"
 	"context"
 	"io"
 	"log/slog"
@@ -8,12 +9,9 @@ import (
 	"net/http/httptest"
 	"sync/atomic"
 	"testing"
-	"time"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
-
-	"github.com/mathiasbq/hyperguild/ingestion/internal/startupretry"
 )
 
 // fakeIssuer answers OIDC discovery with 502 for the first fail requests, as
@@ -41,46 +39,42 @@ func fakeIssuer(t *testing.T, fail int32) (*httptest.Server, *atomic.Int32) {
 	return srv, &discoveries
 }
 
-var fastPolicy = startupretry.Policy{Attempts: 8, Base: time.Millisecond, Max: 5 * time.Millisecond}
-
-func TestBuildJWTValidatorRetriesDiscovery502sThenSucceeds(t *testing.T) {
-	srv, discoveries := fakeIssuer(t, 3)
-	ctx, cancel := context.WithCancel(context.Background())
-	defer cancel()
-
-	v, err := buildJWTValidator(ctx, slog.New(slog.DiscardHandler), srv.URL, "brain", fastPolicy)
+// #83 retried discovery at boot because chassis v0.2.0 failed construction on
+// a 502. Since chassis v0.7 (mcp-chassis#4) the validator is built anyway and
+// resolves the issuer lazily, so boot no longer waits or exits on it
+// (hyperguild#155). An unresolved issuer is logged at boot.
+func TestBuildJWTValidatorReturnsAValidatorWhileDiscovery502s(t *testing.T) {
+	srv, _ := fakeIssuer(t, 1000)
+	var buf bytes.Buffer
+	v, err := buildJWTValidator(context.Background(), slog.New(slog.NewTextHandler(&buf, nil)), srv.URL, "brain")
 	require.NoError(t, err)
 	assert.NotNil(t, v)
-	assert.Equal(t, int32(4), discoveries.Load(), "three 502s, then the successful discovery")
+	assert.Contains(t, buf.String(), "jwt issuer not resolved at boot")
 }
 
-func TestBuildJWTValidatorGivesUpAfterTheBudgetWithTheLastError(t *testing.T) {
-	srv, discoveries := fakeIssuer(t, 1000)
-	ctx, cancel := context.WithCancel(context.Background())
-	defer cancel()
-
-	_, err := buildJWTValidator(ctx, slog.New(slog.DiscardHandler), srv.URL, "brain", fastPolicy)
-	require.Error(t, err)
-	assert.Contains(t, err.Error(), "status 502")
-	assert.Equal(t, int32(8), discoveries.Load(), "bounded: exactly the attempt budget")
+func TestBuildJWTValidatorLogsNothingAgainstAHealthyIssuer(t *testing.T) {
+	srv, _ := fakeIssuer(t, 0)
+	var buf bytes.Buffer
+	v, err := buildJWTValidator(context.Background(), slog.New(slog.NewTextHandler(&buf, nil)), srv.URL, "brain")
+	require.NoError(t, err)
+	assert.NotNil(t, v)
+	assert.NotContains(t, buf.String(), "not resolved")
 }
 
-func TestBuildJWTValidatorStopsRetryingWhenTheContextIsCancelled(t *testing.T) {
+func TestBuildJWTValidatorIsNilWithoutAnIssuer(t *testing.T) {
+	v, err := buildJWTValidator(context.Background(), slog.New(slog.DiscardHandler), "", "brain")
+	require.NoError(t, err)
+	assert.Nil(t, v)
+}
+
+// With the issuer unresolved, a JWT on a REST route answers 503 (retry), not
+// 401: the token may be fine, the server just cannot check it yet.
+func TestBuildMuxAnswers503ToAJWTWhileTheIssuerIsUnresolved(t *testing.T) {
 	srv, _ := fakeIssuer(t, 1000)
-	ctx, cancel := context.WithCancel(context.Background())
-	slow := startupretry.Policy{Attempts: 8, Base: time.Hour, Max: time.Hour}
-
-	done := make(chan error, 1)
-	go func() {
-		_, err := buildJWTValidator(ctx, slog.New(slog.DiscardHandler), srv.URL, "brain", slow)
-		done <- err
-	}()
-	time.Sleep(50 * time.Millisecond)
-	cancel()
-	select {
-	case err := <-done:
-		assert.ErrorIs(t, err, context.Canceled)
-	case <-time.After(3 * time.Second):
-		t.Fatal("did not return after the context was cancelled")
-	}
+	v, err := buildJWTValidator(context.Background(), slog.New(slog.DiscardHandler), srv.URL, "brain")
+	require.NoError(t, err)
+	mux, err := buildMux(restAuth{token: routesTok, validator: v, realm: "brain"}, testHandler(t), nil)
+	require.NoError(t, err)
+	code, _ := do(t, mux, "GET", "/pending", "Bearer aaa.bbb.ccc")
+	assert.Equal(t, http.StatusServiceUnavailable, code)
 }

ingestion/cmd/server/main.go

@@ -32,7 +32,6 @@ import (
 	"github.com/mathiasbq/hyperguild/ingestion/internal/pipeline"
 	"github.com/mathiasbq/hyperguild/ingestion/internal/reranker"
 	"github.com/mathiasbq/hyperguild/ingestion/internal/search"
-	"github.com/mathiasbq/hyperguild/ingestion/internal/startupretry"
 	"github.com/mathiasbq/hyperguild/ingestion/internal/symlinkguard"
 	"github.com/mathiasbq/hyperguild/ingestion/internal/vectorstore"
 	"github.com/mathiasbq/hyperguild/ingestion/internal/watcher"
@@ -369,21 +368,15 @@ func main() {
 	// hyperguild#157: report a symlink that appears in the brain while running.
 	go symlinkguard.Watch(ctx, brainDir, symlinkScanInterval(os.Getenv), buildNotifier())
 
-	// Built before the watcher, the graph backfill and session ingestion, and
-	// retried rather than fatal (#83). Two separate reasons:
-	//
-	//   - On a cold cluster boot this pod can beat dex to serving and gets a
-	//     502 from ingress. Nothing is misconfigured; it simply started first.
-	//     Exiting there meant CrashLoopBackOff redoing the backfill on every
-	//     attempt, with exponential backoff stretching the brain outage.
-	//   - Constructing it first means a genuine config error (wrong issuer,
-	//     bad audience) fails in seconds instead of after all that work.
-	//
-	// The budget stays bounded: retrying forever would turn a misconfiguration
-	// into a process that looks alive and never serves.
+	// Never fatal on an unreachable issuer (#83): on a cold cluster boot this
+	// pod can beat dex to serving and get a 502 from ingress, and exiting meant
+	// CrashLoopBackOff redoing the backfill. Since mcp-chassis v0.7 the
+	// validator resolves the issuer lazily and answers JWTs 503-and-retry until
+	// it does (hyperguild#155), so no boot retry is needed. A misconfigured
+	// issuer no longer exits the process: it is logged at boot and every JWT
+	// gets 503; the static bearer keeps working.
 	jwtValidator, err := buildJWTValidator(ctx, logger,
-		os.Getenv("DEX_ISSUER_URL"), os.Getenv("MCP_AUDIENCE"),
-		startupretry.Policy{Attempts: 8, Base: time.Second, Max: 30 * time.Second})
+		os.Getenv("DEX_ISSUER_URL"), os.Getenv("MCP_AUDIENCE"))
 	if err != nil {
 		logger.Error("build jwt validator", "err", err)
 		os.Exit(1)

ingestion/cmd/server/routes.go

@@ -73,5 +73,23 @@ func mountREST(mux *http.ServeMux, h *api.Handler, auth func(http.Handler) http.
 	rest.HandleFunc("POST /promote", h.Promote)
 	rest.HandleFunc("POST /backfill-embeddings", h.BackfillEmbeddings)
 	rest.HandleFunc("GET /pass-rate", h.PassRate)
-	mux.Handle("/", auth(rest))
+	mux.Handle("/", labelRESTPattern(rest, auth(rest)))
+}
+
+// labelRESTPattern sets the request's Pattern to the REST route it addresses
+// before auth runs, so the metrics middleware (which reads Pattern from the
+// same *http.Request) labels a refused request by its route rather than by
+// the "/" mount (hyperguild#155). A refused request to a path no route
+// matches keeps "/", so for refused requests the label set stays bounded by
+// the registered routes. That bound does not hold for authenticated
+// requests: an unregistered path reaches the REST mux, which 404s with an
+// empty Pattern, and the metrics middleware falls back to the raw URL path
+// (hyperguild#185).
+func labelRESTPattern(rest *http.ServeMux, next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		if _, pattern := rest.Handler(r); pattern != "" {
+			r.Pattern = pattern
+		}
+		next.ServeHTTP(w, r)
+	})
 }

ingestion/cmd/server/routes_observability_test.go

@@ -0,0 +1,90 @@
+package main
+
+import (
+	"bytes"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+
+	"github.com/mathiasbq/hyperguild/ingestion/internal/metrics"
+)
+
+// wrongTokSentinel is a presented credential distinctive enough that any
+// occurrence in a log line is the raw token, not a coincidence.
+const wrongTokSentinel = "wrong-tok-sentinel-q7zx"
+
+// hyperguild#155: since #149 every REST route sits behind BearerMiddleware,
+// and chassis v0.2.0 refused without logging, so an unknown caller got
+// silent 401s. The chassis now writes an `mcp auth rejected` line, and the
+// presented token appears nowhere in the log as a bare value (PR #181
+// review: asserting on the "Bearer " header form could never fail, since
+// the chassis logs fields, not headers).
+func TestBuildMuxRejectionLogLineOmitsTheBarePresentedToken(t *testing.T) {
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil)))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+
+	code, _ := do(t, testMux(t), "POST", "/query", "Bearer "+wrongTokSentinel)
+	require.Equal(t, http.StatusUnauthorized, code)
+	assert.Contains(t, buf.String(), "mcp auth rejected")
+	assert.Contains(t, buf.String(), "path=/query")
+	assert.NotContains(t, buf.String(), wrongTokSentinel, "the rejected token is logged as a bare value")
+	assert.NotContains(t, buf.String(), routesTok, "the valid static token is logged")
+}
+
+// The `mcp auth accepted` line leaves out the valid static token.
+func TestBuildMuxAcceptedLogLineOmitsTheBareStaticToken(t *testing.T) {
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil)))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+
+	code, _ := do(t, testMux(t), "GET", "/pending", "Bearer "+routesTok)
+	require.Equal(t, http.StatusOK, code)
+	assert.Contains(t, buf.String(), "mcp auth accepted")
+	assert.NotContains(t, buf.String(), routesTok, "the accepted static token is logged as a bare value")
+}
+
+// An authenticated REST request is labelled with the REST mux's pattern:
+// the inner mux sets it on the same *http.Request the outer middleware reads.
+func TestMetricsLabelAnAuthenticatedRESTRequestWithItsRoutePattern(t *testing.T) {
+	reg := metrics.New()
+	code, _ := do(t, reg.Middleware(testMux(t)), "GET", "/pending", "Bearer "+routesTok)
+	require.Equal(t, http.StatusOK, code)
+
+	rec := httptest.NewRecorder()
+	reg.Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
+	assert.Contains(t, rec.Body.String(), `path="GET /pending"`)
+	assert.NotContains(t, rec.Body.String(), `path="/"`)
+}
+
+// hyperguild#155: a request refused by REST auth never reaches the REST mux,
+// so it was labelled path="/" and a 4xx on /query could not be told from one
+// on /write. It is now labelled with the REST pattern it was addressed to.
+func TestMetricsLabelARejectedRESTRequestWithItsRoutePattern(t *testing.T) {
+	reg := metrics.New()
+	code, _ := do(t, reg.Middleware(testMux(t)), "POST", "/query", "")
+	require.Equal(t, http.StatusUnauthorized, code)
+
+	rec := httptest.NewRecorder()
+	reg.Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
+	assert.Contains(t, rec.Body.String(), `path="POST /query",status="4xx"`)
+}
+
+// A path no REST route matches keeps the catch-all label, so an attacker
+// probing random URLs cannot grow the series set.
+func TestMetricsLabelARejectedUnknownPathWithTheCatchAll(t *testing.T) {
+	reg := metrics.New()
+	code, _ := do(t, reg.Middleware(testMux(t)), "POST", "/no-such-route-zq", "")
+	require.Equal(t, http.StatusUnauthorized, code)
+
+	rec := httptest.NewRecorder()
+	reg.Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
+	assert.Contains(t, rec.Body.String(), `path="/",status="4xx"`)
+	assert.NotContains(t, rec.Body.String(), "no-such-route-zq")
+}

ingestion/cmd/server/routes_test.go

@@ -27,7 +27,7 @@ func okHandler(body string) http.Handler {
 // review showed a test of a COPY of the router let main.go regress unseen.
 func testMux(t *testing.T) http.Handler {
 	t.Helper()
-	h := api.NewHandler(t.TempDir(), slog.New(slog.NewTextHandler(os.Stderr, nil)), pipeline.Config{})
+	h := testHandler(t)
 	public := map[string]http.Handler{}
 	for p := range publicRoutes {
 		public[p] = okHandler("public " + p)
@@ -37,6 +37,11 @@ func testMux(t *testing.T) http.Handler {
 	return mux
 }
 
+func testHandler(t *testing.T) *api.Handler {
+	t.Helper()
+	return api.NewHandler(t.TempDir(), slog.New(slog.NewTextHandler(os.Stderr, nil)), pipeline.Config{})
+}
+
 func do(t *testing.T, h http.Handler, method, path, authz string) (int, string) {
 	t.Helper()
 	req := httptest.NewRequest(method, path, strings.NewReader(`{"query":"x"}`))