summercms/modules/surf/accesslog_test.go

package surf

import (
	"bytes"
	"context"
	"encoding/json"
	"log/slog"
	"net/http"
	"net/http/httptest"
	"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)
			}
		})
	}
}