Jakub Zych
fbcfaaf05f
An unmatched request logged its path. A token route reached with another method (405) or with a trailing slash (404) is answered by ServeMux before any route handler records the pattern, so the share or invitation token in the path reached the log. The record now carries method, pattern, status and duration only.
351 lines
12 KiB
Go
351 lines
12 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())
|
|
}
|
|
}
|
|
|
|
// A 5xx written after the client cancelled the request is logged as 499;
|
|
// a 5xx on a live request keeps its status.
|
|
func TestAccessLogClientClosedRequest(t *testing.T) {
|
|
for _, tc := range []struct {
|
|
name string
|
|
cancel bool
|
|
want float64
|
|
}{
|
|
{"cancelled", true, 499},
|
|
{"live", false, 500},
|
|
} {
|
|
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, http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
|
|
if tc.cancel {
|
|
cancel()
|
|
}
|
|
w.WriteHeader(http.StatusInternalServerError)
|
|
}))
|
|
req := httptest.NewRequest(http.MethodGet, "/blog/posts/7", nil).WithContext(ctx)
|
|
h.ServeHTTP(httptest.NewRecorder(), req)
|
|
recs := accessRecords(t, &buf)
|
|
if len(recs) != 1 || recs[0]["status"] != tc.want {
|
|
t.Fatalf("records=%v, want one with status %v", recs, tc.want)
|
|
}
|
|
})
|
|
}
|
|
}
|
|
|
|
// 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)
|
|
}
|
|
}
|