From fedc3650b582b565a2c272085adf7fdae722f5b9 Mon Sep 17 00:00:00 2001 From: ZDDC Date: Thu, 30 Apr 2026 12:46:49 -0500 Subject: [PATCH] fix(zddc-server): access log was always email=anonymous (middleware ordering) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The middleware chain in main.go was: AccessLogMiddleware ( CORSMiddleware ( ACLMiddleware ( dispatch ) ) ) ACLMiddleware extracts the user email from the configured header and stores it in the request context via r.WithContext. But Go's context propagates DOWN the chain (to handlers further in) — not back UP. The new context-bearing request only exists inside the call to next.ServeHTTP; once that returns, the outer middleware still has the ORIGINAL request without the email. So AccessLogMiddleware's EmailFromContext(r) call (which runs after next.ServeHTTP returns to log the request) read from the original context and got an empty string, falling through to "anonymous". The /.profile/ page worked correctly because it reads the email directly inside the handler — at that depth the context-bearing request is the one in scope. Fix: invert the chain so ACL is OUTERMOST. ACLMiddleware ( AccessLogMiddleware ( CORSMiddleware ( dispatch ) ) ) Now ACL extracts the email and the new request flows down through AccessLog (which sees the email-bearing context), CORS, and dispatch. Add three regression tests in middleware_test.go: TestAccessLogReadsEmailFromACLContext The fix: with ACL outer, AccessLog logs email=alice@example.com when X-Auth-Request-Email is set. TestAccessLogAnonymousWhenNoEmail The unchanged path: no header → email=anonymous (correct fallback). TestAccessLogOuterDoesNotSeeInnerContext Locks down Go's actual context-propagation behavior. Builds the INVERTED (buggy) chain and asserts that AccessLog (outer) does NOT see the email ACL (inner) set. If this ever fails, Go's context propagation has changed in a way that lets inner-set context flow upward — which would mean the reordering fix could be reverted. All zddc-server tests pass via `go test ./...` (run in podman against golang:1.24-alpine since this dev host doesn't have Go installed). Co-Authored-By: Claude Opus 4.7 (1M context) --- zddc/cmd/zddc-server/main.go | 14 ++- zddc/internal/handler/middleware_test.go | 106 +++++++++++++++++++++++ 2 files changed, 119 insertions(+), 1 deletion(-) create mode 100644 zddc/internal/handler/middleware_test.go diff --git a/zddc/cmd/zddc-server/main.go b/zddc/cmd/zddc-server/main.go index d0c3291..75fbb64 100644 --- a/zddc/cmd/zddc-server/main.go +++ b/zddc/cmd/zddc-server/main.go @@ -65,7 +65,19 @@ func main() { // HTTP handler mux := http.NewServeMux() - mux.Handle("/", handler.AccessLogMiddleware(handler.CORSMiddleware(cfg, handler.ACLMiddleware(cfg, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Middleware chain (outermost → innermost): + // ACLMiddleware — extract email from cfg.EmailHeader, store in + // request context. Outermost so the email is + // available to AccessLogMiddleware (Go's context + // propagates DOWN the chain via r.WithContext, not + // UP — so AccessLog can't read a context value set + // by an inner middleware after next.ServeHTTP + // returns). + // AccessLogMiddleware — structured per-request log; reads email from + // the context the outer ACL middleware set. + // CORSMiddleware — Origin / preflight handling. + // dispatch — the actual request handler. + mux.Handle("/", handler.ACLMiddleware(cfg, handler.AccessLogMiddleware(handler.CORSMiddleware(cfg, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { dispatch(cfg, idx, logRing, w, r) }))))) diff --git a/zddc/internal/handler/middleware_test.go b/zddc/internal/handler/middleware_test.go new file mode 100644 index 0000000..cdaceb4 --- /dev/null +++ b/zddc/internal/handler/middleware_test.go @@ -0,0 +1,106 @@ +package handler + +import ( + "bytes" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "codeberg.org/VARASYS/ZDDC/zddc/internal/config" +) + +// TestAccessLogReadsEmailFromACLContext is a regression test for a bug where +// the access-log middleware logged email=anonymous on every request because +// it sat OUTSIDE the ACL middleware in the chain — Go's context propagates +// down via r.WithContext, not back up through the call chain, so an outer +// middleware can't read a context value set by an inner one after +// next.ServeHTTP returns. Fix: ACLMiddleware must wrap AccessLogMiddleware +// (ACL outer), not the other way around. +func TestAccessLogReadsEmailFromACLContext(t *testing.T) { + // Capture slog output so we can assert on what AccessLogMiddleware logged. + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil))) + defer slog.SetDefault(prev) + + cfg := config.Config{EmailHeader: "X-Auth-Request-Email"} + noop := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + // Correct order: ACL is outer, AccessLog is inner. AccessLog reads + // email from the context ACL populated. + chain := ACLMiddleware(cfg, AccessLogMiddleware(noop)) + + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + req.Header.Set("X-Auth-Request-Email", "alice@example.com") + chain.ServeHTTP(httptest.NewRecorder(), req) + + got := buf.String() + if !strings.Contains(got, `email=alice@example.com`) { + t.Errorf("expected access log to contain email=alice@example.com, got: %s", got) + } + if strings.Contains(got, `email=anonymous`) { + t.Errorf("access log fell back to email=anonymous despite header being set; ACL/AccessLog order may have regressed: %s", got) + } +} + +// TestAccessLogAnonymousWhenNoEmail confirms that when the configured email +// header is absent, the access log still records email=anonymous as expected. +func TestAccessLogAnonymousWhenNoEmail(t *testing.T) { + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil))) + defer slog.SetDefault(prev) + + cfg := config.Config{EmailHeader: "X-Auth-Request-Email"} + noop := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + chain := ACLMiddleware(cfg, AccessLogMiddleware(noop)) + + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + // Note: no X-Auth-Request-Email header set. + chain.ServeHTTP(httptest.NewRecorder(), req) + + got := buf.String() + if !strings.Contains(got, `email=anonymous`) { + t.Errorf("expected access log to contain email=anonymous when header absent, got: %s", got) + } +} + +// TestAccessLogOuterDoesNotSeeInnerContext is a guard test that locks down +// the underlying Go behavior: putting AccessLog OUTER and ACL INNER produces +// the original bug (email=anonymous despite the header being set). If this +// test ever fails, Go's context propagation has changed in a way that lets +// inner-middleware context values flow back up — which would mean the +// reordering fix can be reverted. +func TestAccessLogOuterDoesNotSeeInnerContext(t *testing.T) { + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewTextHandler(&buf, nil))) + defer slog.SetDefault(prev) + + cfg := config.Config{EmailHeader: "X-Auth-Request-Email"} + noop := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + // Inverted order — the ORIGINAL buggy chain. + chain := AccessLogMiddleware(ACLMiddleware(cfg, noop)) + + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + req.Header.Set("X-Auth-Request-Email", "alice@example.com") + chain.ServeHTTP(httptest.NewRecorder(), req) + + got := buf.String() + if strings.Contains(got, `email=alice@example.com`) { + t.Fatalf("Go's context propagation behavior changed — AccessLog (outer) somehow saw the email ACL (inner) set. The middleware reordering in main.go is no longer required and could be reverted. Log: %s", got) + } + if !strings.Contains(got, `email=anonymous`) { + t.Errorf("expected the inverted (buggy) chain to fall back to email=anonymous, got: %s", got) + } +}