ZDDC/zddc/internal/handler/middleware_test.go
ZDDC fedc3650b5 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>
2026-04-30 12:46:49 -05:00

106 lines
4 KiB
Go

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