Jakub Zych
c30145ed25
Every 5xx became 499 once the request context was cancelled, so a panic or a real database error on a request the browser had abandoned passed the phase gate's 5xx scan. Now a 5xx is logged as 499 only when the client had already gone when the status was written and the handler did not panic; recoverJSON and recoverBare mark the access log entry. Every record of an abandoned request carries client_gone=true. The gate self-test plants a 5xx with client_gone=true and must refuse it.
397 lines
14 KiB
Go
397 lines
14 KiB
Go
package surf
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"encoding/json"
|
|
"log/slog"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"strconv"
|
|
"strings"
|
|
"testing"
|
|
|
|
"git.golem15.com/golem15/summercms/modules/backpack"
|
|
"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 set to on
|
|
// 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: true\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()
|
|
h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/blog/posts/7?token=secret", nil))
|
|
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:\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 _, 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["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(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(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(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"
|
|
}
|
|
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)
|
|
}
|
|
}
|