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