summercms/modules/surf/accesslog_test.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) || r["path"] != "/acme/missing" {
		t.Fatalf("unmatched record = %v", r)
	}
	if strings.Contains(buf.String(), "secret") {
		t.Fatalf("unmatched record leaks the 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 gets status 404 and its path without
// the query; 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
		path    string // "" means the record must have no path
	}
	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, "/acme/missing"}},
		{"/pl/blog/posts/8?token=query-secret", http.StatusOK, want{"GET /blog/posts/{id}", 200, ""}},
	}
	request := func(target string) *http.Request {
		req := httptest.NewRequest(http.MethodGet, 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()
		h.ServeHTTP(rec, request(tc.target))
		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"] != "GET" || 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)
		}
		path, hasPath := r["path"]
		if tc.want.path == "" && hasPath {
			t.Fatalf("GET %s: a matched record carries path: %v", tc.target, r)
		}
		if tc.want.path != "" && path != tc.want.path {
			t.Fatalf("GET %s: path = %v, want %q", tc.target, path, tc.want.path)
		}
		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/",
		} {
			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)
	}
}