fix(zddc-server): access log was always email=anonymous (middleware ordering)

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) <noreply@anthropic.com>

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)
 	})))))
 

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)
+	}
+}