summercms/modules/surf/accesslog_test.go

package surf

import (
	"bytes"
	"context"
	"encoding/json"
	"fmt"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"os"
	"path/filepath"
	"strconv"
	"strings"
	"testing"

	"git.golem15.com/golem15/summercms/modules/backpack"
	"git.golem15.com/golem15/summercms/modules/compass"
	"git.golem15.com/golem15/summercms/modules/diary"
	"git.golem15.com/golem15/summercms/modules/pact"
	"git.golem15.com/golem15/summercms/modules/party"
)

// blogPostsPlugin serves GET /blog/posts/{id}.
type blogPostsPlugin struct{}

func (blogPostsPlugin) ID() string                   { return "acme.blog" }
func (blogPostsPlugin) Requires() []string           { return nil }
func (blogPostsPlugin) Register(*backpack.App) error { return nil }
func (blogPostsPlugin) Boot(*backpack.App) error     { return nil }
func (blogPostsPlugin) Routes(r pact.Router) error {
	r.Group("/blog", nil, func(g pact.Router) {
		g.Get("/posts/{id}", func(w http.ResponseWriter, _ *http.Request) {
			w.Header().Set("Content-Type", "application/json")
			_, _ = w.Write([]byte(`{"id":7}`))
		})
	})
	return nil
}

// accessLogRouter assembles the blog plugin with http.access_log left at
// its default (on) or set to false, and a published JSON logger writing
// into the returned buffer.
func accessLogRouter(t *testing.T, on bool) (http.Handler, *bytes.Buffer) {
	t.Helper()
	y := "body_limits:\n  default_bytes: 1024\n  upload_bytes: 1024\n"
	if !on {
		y += "access_log: false\n"
	}
	app := backpack.New(writeHTTPConfig(t, y))
	var buf bytes.Buffer
	if err := app.Publish(slog.New(slog.NewJSONHandler(&buf, nil))); err != nil {
		t.Fatal(err)
	}
	h, err := Assemble(app, []party.Plugin{blogPostsPlugin{}})
	if err != nil {
		t.Fatal(err)
	}
	return h, &buf
}

// accessRecords decodes the "http request" records in buf.
func accessRecords(t *testing.T, buf *bytes.Buffer) []map[string]any {
	t.Helper()
	var out []map[string]any
	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
		if line == "" {
			continue
		}
		var rec map[string]any
		if err := json.Unmarshal([]byte(line), &rec); err != nil {
			t.Fatalf("log line %q: %v", line, err)
		}
		if rec["msg"] == accessLogMessage {
			out = append(out, rec)
		}
	}
	return out
}

func TestAccessLogSmoke(t *testing.T) {
	h, buf := accessLogRouter(t, true)

	rec := httptest.NewRecorder()
	req := httptest.NewRequest(http.MethodGet, "/blog/posts/7?token=secret", nil)
	req.Header.Set("X-Request-Id", "  req-42  ")
	h.ServeHTTP(rec, req)
	if rec.Code != http.StatusOK {
		t.Fatalf("GET /blog/posts/7 = %d", rec.Code)
	}
	recs := accessRecords(t, buf)
	if len(recs) != 1 {
		t.Fatalf("records = %d, want 1 (the request log is on by default):\n%s", len(recs), buf.String())
	}
	r := recs[0]
	if r["method"] != "GET" || r["pattern"] != "GET /blog/posts/{id}" || r["status"] != float64(200) || r["level"] != "INFO" {
		t.Fatalf("matched record = %v", r)
	}
	if r["request_id"] != "req-42" {
		t.Fatalf("request_id = %v, want the trimmed X-Request-Id", r["request_id"])
	}
	if _, ok := r["duration_ms"].(float64); !ok {
		t.Fatalf("matched record has no duration_ms: %v", r)
	}
	if _, ok := r["path"]; ok {
		t.Fatalf("matched record carries path: %v", r)
	}
	if strings.Contains(buf.String(), "secret") || strings.Contains(buf.String(), "/blog/posts/7") {
		t.Fatalf("matched record leaks the raw path or query:\n%s", buf.String())
	}

	buf.Reset()
	rec = httptest.NewRecorder()
	h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/acme/missing?token=secret", nil))
	if rec.Code != http.StatusNotFound {
		t.Fatalf("GET /acme/missing = %d", rec.Code)
	}
	recs = accessRecords(t, buf)
	if len(recs) != 1 {
		t.Fatalf("records = %d, want 1:\n%s", len(recs), buf.String())
	}
	r = recs[0]
	if r["pattern"] != "" || r["status"] != float64(404) {
		t.Fatalf("unmatched record = %v", r)
	}
	if _, ok := r["request_id"]; ok {
		t.Fatalf("a request without X-Request-Id has a request_id: %v", r)
	}

	buf.Reset()
	long := httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil)
	long.Header.Set("X-Request-Id", strings.Repeat("x", 300))
	h.ServeHTTP(httptest.NewRecorder(), long)
	if recs = accessRecords(t, buf); len(recs) != 1 || len(recs[0]["request_id"].(string)) != errorPageMaxRequestID {
		t.Fatalf("a long X-Request-Id is not cut to %d bytes: %v", errorPageMaxRequestID, recs)
	}
	if _, ok := r["path"]; ok {
		t.Fatalf("unmatched record carries path: %v", r)
	}
	if strings.Contains(buf.String(), "secret") || strings.Contains(buf.String(), "/acme/missing") {
		t.Fatalf("unmatched record leaks the path or query:\n%s", buf.String())
	}

	off, offBuf := accessLogRouter(t, false)
	for _, target := range []string{"/blog/posts/7", "/acme/missing"} {
		off.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, target, nil))
	}
	if offBuf.Len() != 0 {
		t.Fatalf("http.access_log off still logged:\n%s", offBuf.String())
	}
}

// TestAccessLogClientClosedRequest: a 5xx is logged as 499 only when the
// client had already gone (the request context ended with context.Canceled)
// when the status was written and the handler did not panic. A 5xx written
// before the client went away keeps its status, and a recovered panic is
// always 500, so a grep for 5xx still finds every real server error. Every
// record of a request whose client went away carries client_gone=true.
func TestAccessLogClientClosedRequest(t *testing.T) {
	type outcome struct {
		status     float64
		clientGone bool
	}
	for _, tc := range []struct {
		name    string
		handler func(cancel context.CancelFunc) http.Handler
		want    outcome
	}{
		{"5xx after the client went away", func(cancel context.CancelFunc) http.Handler {
			return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				cancel()
				w.WriteHeader(http.StatusInternalServerError)
			})
		}, outcome{499, true}},
		{"live 5xx", func(context.CancelFunc) http.Handler {
			return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				w.WriteHeader(http.StatusInternalServerError)
			})
		}, outcome{500, false}},
		{"5xx before the client went away", func(cancel context.CancelFunc) http.Handler {
			return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				w.WriteHeader(http.StatusBadGateway)
				cancel()
			})
		}, outcome{502, true}},
		{"200 then the client went away", func(cancel context.CancelFunc) http.Handler {
			return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				_, _ = w.Write([]byte("ok"))
				cancel()
			})
		}, outcome{200, true}},
		{"5xx through the JSON recovery after the client went away", func(cancel context.CancelFunc) http.Handler {
			return recordPattern("GET /blog/posts/{id}", recoverJSON(nil, http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
				cancel()
				w.WriteHeader(http.StatusInternalServerError)
			})))
		}, outcome{499, true}},
		{"panic after the client went away (JSON group)", func(cancel context.CancelFunc) http.Handler {
			return recordPattern("GET /blog/posts/{id}", recoverJSON(nil, http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
				cancel()
				panic("blog: broken")
			})))
		}, outcome{500, true}},
		{"panic after the client went away (raw group)", func(cancel context.CancelFunc) http.Handler {
			return recordPattern("GET /blog/posts/{id}", recoverBare(nil, http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
				cancel()
				panic("blog: broken")
			})))
		}, outcome{500, true}},
	} {
		t.Run(tc.name, func(t *testing.T) {
			app := backpack.New(writeHTTPConfig(t, "access_log: true\n"))
			var buf bytes.Buffer
			if err := app.Publish(slog.New(slog.NewJSONHandler(&buf, nil))); err != nil {
				t.Fatal(err)
			}
			ctx, cancel := context.WithCancel(t.Context())
			defer cancel()
			h := accessLog(app, tc.handler(cancel))
			req := httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil).WithContext(ctx)
			h.ServeHTTP(httptest.NewRecorder(), req)
			recs := accessRecords(t, &buf)
			if len(recs) != 1 {
				t.Fatalf("records = %v, want one", recs)
			}
			gone, hasGone := recs[0]["client_gone"]
			if recs[0]["status"] != tc.want.status || hasGone != tc.want.clientGone || (hasGone && gone != true) {
				t.Fatalf("record = %v, want status %v client_gone %t", recs[0], tc.want.status, tc.want.clientGone)
			}
		})
	}
}

// blogEdgesPlugin serves the routes TestAccessLog drives: a 200 that
// flushes through http.ResponseController, a handler 404 and a panic.
type blogEdgesPlugin struct{ flushErr *error }

func (blogEdgesPlugin) ID() string                   { return "acme.blog" }
func (blogEdgesPlugin) Requires() []string           { return nil }
func (blogEdgesPlugin) Register(*backpack.App) error { return nil }
func (blogEdgesPlugin) Boot(*backpack.App) error     { return nil }
func (p blogEdgesPlugin) Routes(r pact.Router) error {
	r.Group("/blog", nil, func(g pact.Router) {
		g.Get("/posts/{id}", func(w http.ResponseWriter, _ *http.Request) {
			w.Header().Set("Content-Type", "application/json")
			_, _ = w.Write([]byte(`{"id":7}`))
			*p.flushErr = http.NewResponseController(w).Flush()
		})
		g.Get("/drafts/{id}", func(w http.ResponseWriter, _ *http.Request) {
			http.NotFound(w, nil)
		})
		g.Get("/broken", func(http.ResponseWriter, *http.Request) {
			panic("blog: broken")
		})
	})
	return nil
}

// accessLogEdgesRouter assembles blogEdgesPlugin with http.access_log on
// or off, a JSON logger into the returned buffer and, when locale is set,
// a resolver that strips /pl and /en path prefixes.
func accessLogEdgesRouter(t *testing.T, on, locale bool, flushErr *error) (http.Handler, *bytes.Buffer) {
	t.Helper()
	y := "body_limits:\n  default_bytes: 1024\n  upload_bytes: 1024\n"
	if on {
		y += "access_log: true\n"
	} else {
		y += "access_log: false\n"
	}
	app := backpack.New(writeHTTPConfig(t, y))
	var buf bytes.Buffer
	if err := app.Publish(slog.New(slog.NewJSONHandler(&buf, nil))); err != nil {
		t.Fatal(err)
	}
	if locale {
		if err := app.Publish[LocaleResolver](pathLocaleResolver{}); err != nil {
			t.Fatal(err)
		}
	}
	h, err := Assemble(app, []party.Plugin{blogEdgesPlugin{flushErr: flushErr}})
	if err != nil {
		t.Fatal(err)
	}
	return h, &buf
}

// accessRawRecords decodes the "http request" records keeping numbers as
// written, so an integer field can be told from a float.
func accessRawRecords(t *testing.T, buf *bytes.Buffer) []map[string]any {
	t.Helper()
	var out []map[string]any
	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
		if line == "" {
			continue
		}
		dec := json.NewDecoder(strings.NewReader(line))
		dec.UseNumber()
		var rec map[string]any
		if err := dec.Decode(&rec); err != nil {
			t.Fatalf("log line %q: %v", line, err)
		}
		if rec["msg"] == accessLogMessage {
			out = append(out, rec)
		}
	}
	return out
}

// TestAccessLog: off, nothing is logged. On, one record per request with
// the matched pattern and status for a 200, a handler 404 and a recovered
// panic (500); an unmatched request (a 404, a 405 for a route reached with
// another method, a trailing-slash 404) gets an empty pattern and no path;
// a locale-prefixed request still records the route pattern;
// duration_ms is a non-negative integer; no record carries the query
// string, a header name or value or the Authorization value; and a
// handler's http.ResponseController flush keeps working.
func TestAccessLog(t *testing.T) {
	type want struct {
		pattern string
		status  int64
	}
	cases := []struct {
		target string
		code   int
		want   want
	}{
		{"/blog/posts/7?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200}},
		{"/blog/drafts/9?token=query-secret", http.StatusNotFound, want{"GET /blog/drafts/{id}", 404}},
		{"/blog/broken?token=query-secret", http.StatusInternalServerError, want{"GET /blog/broken", 500}},
		{"/acme/missing?token=query-secret", http.StatusNotFound, want{"", 404}},
		{"/pl/blog/posts/8?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200}},
		// A token route reached with another method (405) or a trailing
		// slash (404) matches no route: ServeMux answers before any route
		// handler runs, so the path segment must not reach the log.
		{"POST /blog/posts/path-secret-405", http.StatusMethodNotAllowed, want{"", 405}},
		{"/blog/posts/path-secret-404/", http.StatusNotFound, want{"", 404}},
	}
	request := func(target string) *http.Request {
		method := http.MethodGet
		if m, rest, ok := strings.Cut(target, " "); ok {
			method, target = m, rest
		}
		req := httptest.NewRequest(method, target, nil)
		req.Header.Set("Authorization", "Bearer authz-secret-value")
		req.Header.Set("X-Blog-Probe", "probe-header-value")
		req.Header.Set("Cookie", "session=cookie-secret-value")
		return req
	}

	var flushErr error
	off, offBuf := accessLogEdgesRouter(t, false, true, &flushErr)
	for _, tc := range cases {
		off.ServeHTTP(httptest.NewRecorder(), request(tc.target))
	}
	if offBuf.Len() != 0 {
		t.Fatalf("http.access_log off still logged:\n%s", offBuf.String())
	}

	h, buf := accessLogEdgesRouter(t, true, true, &flushErr)
	for _, tc := range cases {
		buf.Reset()
		flushErr = context.Canceled
		rec := httptest.NewRecorder()
		req := request(tc.target)
		h.ServeHTTP(rec, req)
		if rec.Code != tc.code {
			t.Fatalf("GET %s = %d, want %d", tc.target, rec.Code, tc.code)
		}
		if tc.want.status == 200 && flushErr != nil {
			t.Fatalf("GET %s: http.ResponseController flush = %v", tc.target, flushErr)
		}
		recs := accessRawRecords(t, buf)
		if len(recs) != 1 {
			t.Fatalf("GET %s: records = %d, want 1:\n%s", tc.target, len(recs), buf.String())
		}
		r := recs[0]
		status, err := r["status"].(json.Number).Int64()
		if err != nil || r["method"] != req.Method || r["pattern"] != tc.want.pattern || status != tc.want.status || r["level"] != "INFO" {
			t.Fatalf("GET %s: record %v, want pattern %q status %d", tc.target, r, tc.want.pattern, tc.want.status)
		}
		d, ok := r["duration_ms"].(json.Number)
		if !ok {
			t.Fatalf("GET %s: duration_ms missing: %v", tc.target, r)
		}
		if n, err := strconv.ParseInt(d.String(), 10, 64); err != nil || n < 0 {
			t.Fatalf("GET %s: duration_ms %q is not a non-negative integer", tc.target, d)
		}
		if _, hasPath := r["path"]; hasPath {
			t.Fatalf("GET %s: the record carries path: %v", tc.target, r)
		}
		for _, leak := range []string{
			"query-secret", "token=", "authz-secret-value", "Authorization", "Bearer",
			"X-Blog-Probe", "probe-header-value", "cookie-secret-value", "Cookie",
			"/blog/posts/7", "/blog/posts/8", "/pl/", "path-secret", "/acme/missing",
		} {
			if strings.Contains(buf.String(), leak) {
				t.Fatalf("GET %s: the log carries %q:\n%s", tc.target, leak, buf.String())
			}
		}
	}

	// Flush passes through the recorder to the client's writer.
	app := backpack.New(writeHTTPConfig(t, "access_log: true\n"))
	var direct bytes.Buffer
	if err := app.Publish(slog.New(slog.NewJSONHandler(&direct, nil))); err != nil {
		t.Fatal(err)
	}
	var directErr error
	rec := httptest.NewRecorder()
	accessLog(app, http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
		_, _ = w.Write([]byte("chunk"))
		directErr = http.NewResponseController(w).Flush()
	})).ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/blog/stream", nil))
	if directErr != nil || !rec.Flushed {
		t.Fatalf("flush through the access log: err=%v flushed=%t", directErr, rec.Flushed)
	}
	if recs := accessRecords(t, &direct); len(recs) != 1 || recs[0]["status"] != float64(200) {
		t.Fatalf("direct records = %v", recs)
	}
}

// sharePlugin serves token-bearing paths: GET /share/{token} and
// POST /invite/{token}.
type sharePlugin struct{}

func (sharePlugin) ID() string                   { return "acme.share" }
func (sharePlugin) Requires() []string           { return nil }
func (sharePlugin) Register(*backpack.App) error { return nil }
func (sharePlugin) Boot(*backpack.App) error     { return nil }
func (sharePlugin) Routes(r pact.Router) error {
	r.Get("/share/{token}", func(w http.ResponseWriter, _ *http.Request) { _, _ = w.Write([]byte("ok")) })
	r.Post("/invite/{token}", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusNoContent) })
	return nil
}

// diaryAccessRouter assembles plugin with httpYAML and no published
// logger, so the request log goes to the diary component http, set up on a
// console buffer with environ.
func diaryAccessRouter(t *testing.T, httpYAML string, plugin party.Plugin, environ ...string) (http.Handler, *syncBuffer) {
	t.Helper()
	app := backpack.New(writeHTTPConfig(t, "body_limits:\n  default_bytes: 1024\n  upload_bytes: 1024\n"+httpYAML))
	h, err := Assemble(app, []party.Plugin{plugin})
	if err != nil {
		t.Fatal(err)
	}
	cfg, err := compass.Open(compass.Options{Dir: t.TempDir(), Environ: append([]string{"SUMMER_LOG__DEFAULT=console"}, environ...)})
	if err != nil {
		t.Fatal(err)
	}
	var buf syncBuffer
	t.Cleanup(diary.Reset)
	if err := diary.Setup(cfg, diary.Options{Stderr: &buf, Root: t.TempDir(), Environ: []string{}}); err != nil {
		t.Fatal(err)
	}
	return h, &buf
}

// TestAccessLogRequestIDCap: X-Request-Id is trimmed, cut to 128 bytes on
// a rune boundary and stripped of invalid UTF-8.
func TestAccessLogRequestIDCap(t *testing.T) {
	h, buf := accessLogRouter(t, true)
	cases := map[string]string{
		strings.Repeat("a", 300):                strings.Repeat("a", errorPageMaxRequestID),
		"\t  req-7 \t":                          "req-7",
		strings.Repeat("a", 127) + "é" + "tail": strings.Repeat("a", 127),
		"bad\xffid":                             "badid",
	}
	for header, want := range cases {
		buf.Reset()
		req := httptest.NewRequest(http.MethodGet, "/blog/posts/1", nil)
		req.Header["X-Request-Id"] = []string{header}
		h.ServeHTTP(httptest.NewRecorder(), req)
		recs := accessRecords(t, buf)
		if len(recs) != 1 || recs[0]["request_id"] != want {
			t.Errorf("X-Request-Id %q: records %v, want request_id %q", header, recs, want)
		}
		if id, _ := recs[0]["request_id"].(string); len(id) > errorPageMaxRequestID {
			t.Errorf("request_id is %d bytes", len(id))
		}
	}
	buf.Reset()
	req := httptest.NewRequest(http.MethodGet, "/blog/posts/1", nil)
	req.Header.Set("X-Request-Id", "   ")
	h.ServeHTTP(httptest.NewRecorder(), req)
	if recs := accessRecords(t, buf); len(recs) != 1 || recs[0]["request_id"] != nil {
		t.Errorf("a blank X-Request-Id gives %v, want no request_id", recs)
	}
}

// TestAccessLogDefaultOn: without http.access_log, and with it true, every
// request is logged once.
func TestAccessLogDefaultOn(t *testing.T) {
	for name, yaml := range map[string]string{"unset": "", "true": "access_log: true\n"} {
		h, buf := diaryAccessRouter(t, yaml, blogPostsPlugin{})
		for range 3 {
			h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil))
		}
		if n := strings.Count(buf.String(), `msg="http request"`); n != 3 {
			t.Errorf("%s: %d request records, want 3:\n%s", name, n, buf.String())
		}
	}
}

// TestAccessLogDisabled: http.access_log false, also as the string an
// environment variable gives, turns the request log off.
func TestAccessLogDisabled(t *testing.T) {
	h, buf := diaryAccessRouter(t, "access_log: false\n", blogPostsPlugin{})
	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil))
	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/nowhere", nil))
	if strings.Contains(buf.String(), "http request") {
		t.Errorf("access_log false still logged:\n%s", buf.String())
	}

	dir := t.TempDir()
	if err := os.WriteFile(filepath.Join(dir, "http.yaml"), []byte("body_limits:\n  default_bytes: 1024\n  upload_bytes: 1024\n"), 0o644); err != nil {
		t.Fatal(err)
	}
	cfg, err := compass.Open(compass.Options{Dir: dir, Environ: []string{"SUMMER_ENV=development", "SUMMER_HTTP__ACCESS_LOG=false"}})
	if err != nil {
		t.Fatal(err)
	}
	if accessLogEnabled(backpack.New(cfg)) {
		t.Error("SUMMER_HTTP__ACCESS_LOG=false does not turn the request log off")
	}
	if !accessLogEnabled(nil) || !accessLogEnabled(backpack.New(nil)) {
		t.Error("the request log is off without a config")
	}
}

// TestAccessLogNeverLogsPath: token-bearing paths and queries never reach
// the request log, for a matched route, a 404 (trailing slash) and a 405
// (wrong method), on the default diary console.
func TestAccessLogNeverLogsPath(t *testing.T) {
	h, buf := diaryAccessRouter(t, "", sharePlugin{})
	cases := []struct {
		method, target string
		status         int
		pattern        string
	}{
		{http.MethodGet, "/share/tok-secret-200?sig=query-secret", http.StatusOK, `pattern="GET /share/{token}"`},
		{http.MethodGet, "/share/tok-secret-404/?sig=query-secret", http.StatusNotFound, `pattern=""`},
		{http.MethodDelete, "/share/tok-secret-405?sig=query-secret", http.StatusMethodNotAllowed, `pattern=""`},
		{http.MethodGet, "/invite/tok-secret-invite", http.StatusMethodNotAllowed, `pattern=""`},
		{http.MethodPost, "/invite/tok-secret-post", http.StatusNoContent, `pattern="POST /invite/{token}"`},
	}
	for _, tc := range cases {
		rec := httptest.NewRecorder()
		h.ServeHTTP(rec, httptest.NewRequest(tc.method, tc.target, nil))
		if rec.Code != tc.status {
			t.Fatalf("%s %s = %d, want %d", tc.method, tc.target, rec.Code, tc.status)
		}
	}
	got := buf.String()
	lines := strings.Split(strings.TrimSpace(got), "\n")
	if len(lines) != len(cases) {
		t.Fatalf("want %d request records, got %d:\n%s", len(cases), len(lines), got)
	}
	for i, tc := range cases {
		if !strings.Contains(lines[i], tc.pattern) || !strings.Contains(lines[i], fmt.Sprintf("status=%d", tc.status)) {
			t.Errorf("record %d = %q, want %s status=%d", i, lines[i], tc.pattern, tc.status)
		}
	}
	for _, leak := range []string{"tok-secret", "query-secret", "sig=", "/share/tok", "/invite/tok"} {
		if strings.Contains(got, leak) {
			t.Errorf("the request log carries %q:\n%s", leak, got)
		}
	}
}

// TestAccessLogComponentHTTP: without a published logger the request log
// is the diary component http, so log.components.http: warn silences it.
func TestAccessLogComponentHTTP(t *testing.T) {
	h, buf := diaryAccessRouter(t, "", blogPostsPlugin{})
	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil))
	if !strings.Contains(buf.String(), "component=http") || !strings.Contains(buf.String(), "level=INFO") {
		t.Errorf("request record lacks component=http:\n%s", buf.String())
	}

	quiet, qbuf := diaryAccessRouter(t, "", blogPostsPlugin{}, "SUMMER_LOG__COMPONENTS__HTTP=warn")
	quiet.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil))
	if strings.Contains(qbuf.String(), "http request") {
		t.Errorf("log.components.http warn still logged:\n%s", qbuf.String())
	}
}