minstrel/internal/server/requestlog_test.go

package server

import (
	"bytes"
	"context"
	"encoding/json"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"strings"
	"testing"
)

// captureLogger is a slog.Handler that records each Record emitted, so
// requestLog tests can assert level + attrs without parsing JSON.
type capturedRecord struct {
	Level slog.Level
	Msg   string
	Attrs map[string]any
}

type captureHandler struct {
	records *[]capturedRecord
}

func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true }

func (h *captureHandler) Handle(_ context.Context, r slog.Record) error {
	rec := capturedRecord{Level: r.Level, Msg: r.Message, Attrs: map[string]any{}}
	r.Attrs(func(a slog.Attr) bool { rec.Attrs[a.Key] = a.Value.Any(); return true })
	*h.records = append(*h.records, rec)
	return nil
}

func (h *captureHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h }
func (h *captureHandler) WithGroup(_ string) slog.Handler      { return h }

func newCaptureLogger() (*slog.Logger, *[]capturedRecord) {
	records := &[]capturedRecord{}
	return slog.New(&captureHandler{records: records}), records
}

func TestRequestLog_StatusToSeverity(t *testing.T) {
	cases := []struct {
		name      string
		status    int
		wantLevel slog.Level
	}{
		{"2xx is Info", http.StatusOK, slog.LevelInfo},
		{"4xx is Warn", http.StatusNotFound, slog.LevelWarn},
		{"5xx is Error", http.StatusInternalServerError, slog.LevelError},
	}
	for _, tc := range cases {
		t.Run(tc.name, func(t *testing.T) {
			logger, records := newCaptureLogger()
			h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				w.WriteHeader(tc.status)
			}))
			req := httptest.NewRequest(http.MethodGet, "/something", nil)
			h.ServeHTTP(httptest.NewRecorder(), req)

			if len(*records) != 1 {
				t.Fatalf("len(records) = %d, want 1", len(*records))
			}
			rec := (*records)[0]
			if rec.Level != tc.wantLevel {
				t.Errorf("level = %v, want %v", rec.Level, tc.wantLevel)
			}
			if rec.Attrs["status"] != int64(tc.status) {
				t.Errorf("status = %v, want %d", rec.Attrs["status"], tc.status)
			}
		})
	}
}

func TestRequestLog_SkipsHealthz(t *testing.T) {
	logger, records := newCaptureLogger()
	h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		w.WriteHeader(http.StatusOK)
	}))
	req := httptest.NewRequest(http.MethodGet, "/healthz", nil)
	h.ServeHTTP(httptest.NewRecorder(), req)

	if len(*records) != 0 {
		t.Errorf("expected /healthz to be skipped, got %d records", len(*records))
	}
}

// Sanity that other paths produce a useful structured payload.
func TestRequestLog_AttributesPresent(t *testing.T) {
	// Use a real slog text handler buffer so we also exercise the
	// formatter (catches WithAttrs/WithGroup integration regressions).
	var buf bytes.Buffer
	logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
	h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		w.WriteHeader(http.StatusOK)
	}))
	req := httptest.NewRequest(http.MethodPost, "/api/something", strings.NewReader(""))
	h.ServeHTTP(httptest.NewRecorder(), req)

	var got map[string]any
	if err := json.Unmarshal(buf.Bytes(), &got); err != nil {
		t.Fatalf("decode log line: %v\nraw: %s", err, buf.String())
	}
	for _, key := range []string{"method", "path", "status", "duration_ms", "remote"} {
		if _, ok := got[key]; !ok {
			t.Errorf("expected key %q in log entry, got %v", key, got)
		}
	}
}

// The point of routing #2453 through the access log: behind a proxy, `remote`
// must be the client rather than the proxy, and must agree with what the
// Active-sessions surface records for the same request. Logs and UI
// disagreeing about who connected is worse than either being wrong alone.
func TestRequestLog_RemoteHonoursTrustedProxyDepth(t *testing.T) {
	cases := []struct {
		name       string
		hops       func() int
		remoteAddr string
		forwarded  string
		want       string
	}{
		{
			name:       "nil accessor falls back to the socket peer",
			hops:       nil,
			remoteAddr: "203.0.113.200:40000",
			forwarded:  "198.51.100.7",
			want:       "203.0.113.200",
		},
		{
			name:       "depth 0 ignores a forwarded header",
			hops:       func() int { return 0 },
			remoteAddr: "203.0.113.200:40000",
			forwarded:  "198.51.100.7",
			want:       "203.0.113.200",
		},
		{
			// The case that motivated the change: proxy on a PUBLIC address,
			// which the pre-#2453 heuristic logged as the proxy forever.
			name:       "depth 1 through a public-addressed proxy logs the client",
			hops:       func() int { return 1 },
			remoteAddr: "203.0.113.200:40000",
			forwarded:  "198.51.100.7",
			want:       "198.51.100.7",
		},
		{
			name:       "depth 2 reaches through a cdn to the client",
			hops:       func() int { return 2 },
			remoteAddr: "172.18.0.1:40000",
			forwarded:  "198.51.100.7, 203.0.113.50",
			want:       "198.51.100.7",
		},
	}
	for _, tc := range cases {
		t.Run(tc.name, func(t *testing.T) {
			logger, records := newCaptureLogger()
			h := requestLog(logger, tc.hops)(http.HandlerFunc(
				func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }))
			req := httptest.NewRequest(http.MethodGet, "/api/something", nil)
			req.RemoteAddr = tc.remoteAddr
			req.Header.Set("X-Forwarded-For", tc.forwarded)
			h.ServeHTTP(httptest.NewRecorder(), req)

			if len(*records) != 1 {
				t.Fatalf("len(records) = %d, want 1", len(*records))
			}
			if got := (*records)[0].Attrs["remote"]; got != tc.want {
				t.Errorf("remote = %v, want %q", got, tc.want)
			}
		})
	}
}