Log kernel-images-api as JSON

server/cmd/api/main.go

@@ -46,7 +46,11 @@ import (
 )
 
 func main() {
-	slogger := slog.New(slog.NewTextHandler(os.Stdout, nil))
+	// JSON, so the host's log pipeline can index fields without parsing text.
+	// Fields meant for indexing go under logger.AttrsKey. SetDefault also
+	// routes slog.Default() and the standard log package through it.
+	slogger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
+	slog.SetDefault(slogger)
 
 	// Load configuration from environment variables
 	config, err := config.Load()
@@ -67,8 +71,8 @@ func main() {
 	r := chi.NewRouter()
 	r.Use(
 		chiMiddleware.RequestID,
-		chiMiddleware.Logger,
-		chiMiddleware.Recoverer,
+		logger.RequestLogger(slogger),
+		logger.Recoverer(slogger),
 		func(next http.Handler) http.Handler {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 				ctxWithLogger := logger.AddToContext(r.Context(), slogger)
@@ -165,7 +169,7 @@ func main() {
 		// would swallow it. Wire it to a handler that admits that level and counts
 		// drops into otlpMetrics, so backpressure is both logged and scrapable.
 		otlpMetrics = &events.OTLPMetrics{}
-		otelDiag := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo - 1})
+		otelDiag := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo - 1})
 		otel.SetLogger(logr.FromSlogHandler(events.NewDropCountingHandler(otelDiag, otlpMetrics)))
 		otlpExporter = events.NewOTLPExportController(eventStream, events.OTLPConfig{
 			Endpoint:         config.OTLPEndpoint,
@@ -309,8 +313,8 @@ func main() {
 
 	rDevtools := chi.NewRouter()
 	rDevtools.Use(
-		chiMiddleware.Logger,
-		chiMiddleware.Recoverer,
+		logger.RequestLogger(slogger),
+		logger.Recoverer(slogger),
 		func(next http.Handler) http.Handler {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 				ctxWithLogger := logger.AddToContext(r.Context(), slogger)
@@ -348,8 +352,8 @@ func main() {
 	// proxies WebSocket (BiDi) and all other HTTP to the internal ChromeDriver.
 	rChromeDriver := chi.NewRouter()
 	rChromeDriver.Use(
-		chiMiddleware.Logger,
-		chiMiddleware.Recoverer,
+		logger.RequestLogger(slogger),
+		logger.Recoverer(slogger),
 		func(next http.Handler) http.Handler {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 				ctxWithLogger := logger.AddToContext(r.Context(), slogger)
@@ -374,7 +378,7 @@ func main() {
 	// scrapes must not count as session activity) and without per-request
 	// logging (scrapes would drown the logs).
 	rMetrics := chi.NewRouter()
-	rMetrics.Use(chiMiddleware.Recoverer)
+	rMetrics.Use(logger.Recoverer(slogger))
 	metricsCollectors := []metrics.Collector{
 		metrics.NewNetworkCollector(apiService.NetworkMetrics),
 		metrics.NewBrowserLocationCollector(apiService.BrowserLocationMetrics),

server/e2e/e2e_chromium_configure_test.go

@@ -269,7 +269,7 @@ func testChromiumConfigureExtensionLoadStrategies(t *testing.T, image string, te
 			require.NotEqual(t, before, after)
 			require.Equal(t, starts+1, chromiumConfigureStartCount(t, ctx, c))
 			requireConfiguredExtensionActive(t, ctx, c, "configure-partial-one")
-			_, err = execCombinedOutputWithClient(ctx, c, "grep", []string{"-q", "loaded unpacked extension over CDP.*name=configure-partial-one", "/var/log/supervisord/kernel-images-api"})
+			_, err = execCombinedOutputWithClient(ctx, c, "grep", []string{"-q", `"msg":"loaded unpacked extension over CDP".*"name":"configure-partial-one"`, "/var/log/supervisord/kernel-images-api"})
 			require.NoError(t, err)
 		})
 	}

server/lib/logger/http.go

@@ -0,0 +1,107 @@
+package logger
+
+import (
+	"fmt"
+	"log/slog"
+	"net/http"
+	"runtime/debug"
+	"strings"
+	"time"
+
+	"github.com/go-chi/chi/v5"
+	chiMiddleware "github.com/go-chi/chi/v5/middleware"
+)
+
+// AttrsKey groups the fields of a log line that are meant to be indexed by
+// the log pipeline, as opposed to read. The host collector turns only these
+// into searchable attributes, so keep them bounded: no URLs, paths, error
+// text or other free-form values.
+const AttrsKey = "attrs"
+
+// maxPanicMessage bounds the indexed copy of a panic's value. The full value
+// and stack are logged alongside it.
+const maxPanicMessage = 512
+
+// RequestLogger logs one line per request once it completes, at INFO, or WARN
+// for a 4xx and ERROR for a 5xx. It replaces chi's middleware.Logger, which
+// writes free-form text.
+func RequestLogger(log *slog.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			ww := chiMiddleware.NewWrapResponseWriter(w, r.ProtoMajor)
+			start := time.Now()
+			defer func() {
+				status := ww.Status()
+				if status == 0 {
+					status = http.StatusOK
+				}
+				level := slog.LevelInfo
+				switch {
+				case status >= 500:
+					level = slog.LevelError
+				case status >= 400:
+					level = slog.LevelWarn
+				}
+				scheme := "http"
+				if r.TLS != nil {
+					scheme = "https"
+				}
+				elapsed := time.Since(start)
+				args := []any{
+					"method", r.Method,
+					"url", scheme + "://" + r.Host + r.RequestURI,
+					"proto", r.Proto,
+					"remote_addr", r.RemoteAddr,
+					"status", status,
+					"bytes", ww.BytesWritten(),
+					"duration", elapsed.String(),
+				}
+				if id := chiMiddleware.GetReqID(r.Context()); id != "" {
+					args = append(args, "request_id", id)
+				}
+				attrs := []any{
+					"http.request.method", r.Method,
+					"http.response.status_code", status,
+					"duration_ms", elapsed.Milliseconds(),
+				}
+				if rctx := chi.RouteContext(r.Context()); rctx != nil && rctx.RoutePattern() != "" {
+					attrs = append(attrs, "http.route", rctx.RoutePattern())
+				}
+				args = append(args, slog.Group(AttrsKey, attrs...))
+				log.Log(r.Context(), level, "request", args...)
+			}()
+			next.ServeHTTP(ww, r)
+		})
+	}
+}
+
+// Recoverer recovers a panicking handler, logs the panic and its stack as one
+// ERROR line, and answers 500 unless the connection was being upgraded. It
+// replaces chi's middleware.Recoverer, which prints the stack as many lines of
+// text. http.ErrAbortHandler is re-panicked so net/http aborts the response.
+func Recoverer(log *slog.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			defer func() {
+				rvr := recover()
+				if rvr == nil {
+					return
+				}
+				if rvr == http.ErrAbortHandler {
+					panic(rvr)
+				}
+				msg := fmt.Sprint(rvr)
+				indexed := msg
+				if len(indexed) > maxPanicMessage {
+					indexed = strings.ToValidUTF8(indexed[:maxPanicMessage], "")
+				}
+				log.ErrorContext(r.Context(), "panic", "panic", msg, "stack", string(debug.Stack()),
+					slog.Group(AttrsKey, "exception.type", "panic", "exception.message", indexed))
+				if r.Header.Get("Connection") != "Upgrade" {
+					w.WriteHeader(http.StatusInternalServerError)
+				}
+			}()
+			next.ServeHTTP(w, r)
+		})
+	}
+}

server/lib/logger/http_test.go

@@ -0,0 +1,136 @@
+package logger
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/go-chi/chi/v5"
+	chiMiddleware "github.com/go-chi/chi/v5/middleware"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func decodeLines(t *testing.T, buf *bytes.Buffer) []map[string]any {
+	t.Helper()
+	var lines []map[string]any
+	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
+		if line == "" {
+			continue
+		}
+		var m map[string]any
+		require.NoError(t, json.Unmarshal([]byte(line), &m), line)
+		lines = append(lines, m)
+	}
+	return lines
+}
+
+func TestRequestLogger(t *testing.T) {
+	for _, tc := range []struct {
+		status int
+		level  string
+	}{
+		{http.StatusOK, "INFO"},
+		{http.StatusSwitchingProtocols, "INFO"},
+		{http.StatusNotFound, "WARN"},
+		{http.StatusBadGateway, "ERROR"},
+	} {
+		var buf bytes.Buffer
+		log := slog.New(slog.NewJSONHandler(&buf, nil))
+		r := chi.NewRouter()
+		r.Use(chiMiddleware.RequestID, RequestLogger(log))
+		r.Get("/process/{id}", func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(tc.status)
+			_, _ = w.Write([]byte("hi"))
+		})
+
+		req := httptest.NewRequest(http.MethodGet, "/process/abc?x=1", nil)
+		req.Header.Set(chiMiddleware.RequestIDHeader, "hypeman/abc-1")
+		r.ServeHTTP(httptest.NewRecorder(), req)
+
+		lines := decodeLines(t, &buf)
+		require.Len(t, lines, 1)
+		line := lines[0]
+		assert.Equal(t, tc.level, line["level"])
+		assert.Equal(t, "request", line["msg"])
+		assert.Equal(t, "http://example.com/process/abc?x=1", line["url"])
+		assert.Equal(t, "hypeman/abc-1", line["request_id"])
+		assert.EqualValues(t, tc.status, line["status"])
+		if tc.status >= http.StatusOK {
+			assert.EqualValues(t, 2, line["bytes"])
+		}
+		attrs := line[AttrsKey].(map[string]any)
+		assert.Equal(t, "GET", attrs["http.request.method"])
+		assert.EqualValues(t, tc.status, attrs["http.response.status_code"])
+		assert.Equal(t, "/process/{id}", attrs["http.route"])
+		assert.Contains(t, attrs, "duration_ms")
+		assert.NotContains(t, attrs, "url")
+	}
+}
+
+func TestRequestLoggerDefaultsToOK(t *testing.T) {
+	var buf bytes.Buffer
+	log := slog.New(slog.NewJSONHandler(&buf, nil))
+	h := RequestLogger(log)(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}))
+	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil))
+
+	line := decodeLines(t, &buf)[0]
+	assert.Equal(t, "INFO", line["level"])
+	assert.EqualValues(t, http.StatusOK, line["status"])
+	assert.NotContains(t, line, "request_id")
+	assert.NotContains(t, line[AttrsKey], "http.route")
+}
+
+func TestRecoverer(t *testing.T) {
+	var buf bytes.Buffer
+	log := slog.New(slog.NewJSONHandler(&buf, nil))
+	h := RequestLogger(log)(Recoverer(log)(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
+		panic("x" + strings.Repeat("é", 300))
+	})))
+	rec := httptest.NewRecorder()
+	h.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+
+	assert.Equal(t, http.StatusInternalServerError, rec.Code)
+	lines := decodeLines(t, &buf)
+	require.Len(t, lines, 2)
+	panicLine, requestLine := lines[0], lines[1]
+	assert.Equal(t, "ERROR", panicLine["level"])
+	assert.Equal(t, "panic", panicLine["msg"])
+	assert.Equal(t, "x"+strings.Repeat("é", 300), panicLine["panic"])
+	assert.Contains(t, panicLine["stack"], "TestRecoverer")
+	attrs := panicLine[AttrsKey].(map[string]any)
+	assert.Equal(t, "panic", attrs["exception.type"])
+	// Cut at 512 bytes, without the half of a rune that falls on the boundary.
+	assert.Equal(t, "x"+strings.Repeat("é", 255), attrs["exception.message"])
+	assert.Equal(t, "ERROR", requestLine["level"])
+	assert.EqualValues(t, http.StatusInternalServerError, requestLine["status"])
+}
+
+func TestRecovererLeavesUpgradesAlone(t *testing.T) {
+	log := slog.New(slog.NewJSONHandler(&bytes.Buffer{}, nil))
+	h := Recoverer(log)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.WriteHeader(http.StatusSwitchingProtocols)
+		panic("after upgrade")
+	}))
+	req := httptest.NewRequest(http.MethodGet, "/", nil)
+	req.Header.Set("Connection", "Upgrade")
+	rec := httptest.NewRecorder()
+	h.ServeHTTP(rec, req)
+	assert.Equal(t, http.StatusSwitchingProtocols, rec.Code)
+}
+
+func TestRecovererRepanicsAbort(t *testing.T) {
+	var buf bytes.Buffer
+	log := slog.New(slog.NewJSONHandler(&buf, nil))
+	h := Recoverer(log)(http.HandlerFunc(func(http.ResponseWriter, *http.Request) {
+		panic(http.ErrAbortHandler)
+	}))
+	assert.PanicsWithValue(t, http.ErrAbortHandler, func() {
+		h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil))
+	})
+	assert.Empty(t, buf.String())
+}