diff --git a/server/cmd/api/main.go b/server/cmd/api/main.go index c5515778d..983c22e12 100644 --- a/server/cmd/api/main.go +++ b/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), diff --git a/server/e2e/e2e_chromium_configure_test.go b/server/e2e/e2e_chromium_configure_test.go index a69f05daf..26b53b2ef 100644 --- a/server/e2e/e2e_chromium_configure_test.go +++ b/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) }) } diff --git a/server/lib/logger/http.go b/server/lib/logger/http.go new file mode 100644 index 000000000..86d182aac --- /dev/null +++ b/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) + }) + } +} diff --git a/server/lib/logger/http_test.go b/server/lib/logger/http_test.go new file mode 100644 index 000000000..bbb734702 --- /dev/null +++ b/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()) +}