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/e2e/e2e_enterprise_extension_test.go b/server/e2e/e2e_enterprise_extension_test.go index 62bb4dd64..2e0b5660e 100644 --- a/server/e2e/e2e_enterprise_extension_test.go +++ b/server/e2e/e2e_enterprise_extension_test.go @@ -81,8 +81,6 @@ func runEnterpriseExtensionTest(t *testing.T, image string) { t.Log("[test] uploading kernel-like extension first (to simulate prod)") uploadKernelLikeExtension(t, ctx, c) - downloadLogBaseline := extensionDownloadLogSnapshot(t, ctx, c) - // Upload the enterprise test extension through the new endpoint and verify its policy // requirement selects the restart path. versionURL := "http" + strings.TrimPrefix(c.CDPURL(), "ws") + "json/version" @@ -102,9 +100,6 @@ func runEnterpriseExtensionTest(t *testing.T, image string) { t.Log("[test] verifying enterprise policy configuration") waitForEnterprisePolicy(t, ctx, c, 10*time.Second) - t.Log("[test] waiting for Chrome to download extension via enterprise policy") - waitForExtensionDownload(t, ctx, c, downloadLogBaseline, 30*time.Second) - // Check Chrome's extension installation logs checkChromiumLogs(t, ctx, c) @@ -116,7 +111,7 @@ func runEnterpriseExtensionTest(t *testing.T, image string) { t.Log("[test] checking chrome://policy via screenshot") takeChromePolicyScreenshot(t, ctx, c) - // Verify the extension is installed + // Verify the policy download and installation through Chrome state, not access-log paths. t.Log("[test] checking if extension is installed in Chrome's user-data") waitForExtensionInstalled(t, ctx, c, 30*time.Second) @@ -334,123 +329,6 @@ func checkExtractedFiles(t *testing.T, ctx context.Context, c *TestContainer) { } } -// checkExtensionDownloadLogs checks the kernel-images-api logs for extension download requests. -func checkExtensionDownloadLogs(t *testing.T, ctx context.Context, c *TestContainer) { - t.Helper() - - apiLog, err := extensionDownloadLog(ctx, c) - if err != nil { - t.Logf("[logs] error=%v", err) - return - } - - lines := strings.Split(apiLog, "\n") - for _, line := range lines { - if strings.Contains(line, "update.xml") || strings.Contains(line, ".crx") || strings.Contains(line, "extension") { - t.Logf("[logs] line=%s", line) - } - } - - // Check specifically for GET requests to our extension - if strings.Contains(apiLog, "GET") && strings.Contains(apiLog, "enterprise-test") { - t.Log("[logs] Chrome made GET requests to fetch the extension!") - } else { - t.Log("[logs] No GET requests to enterprise-test extension found") - } - - // Log all GET requests - for _, line := range lines { - if strings.Contains(line, "GET") { - t.Logf("[logs] GET_request=%s", line) - } - } -} - -func extensionDownloadLogSnapshot(t *testing.T, ctx context.Context, c *TestContainer) string { - t.Helper() - apiLog, err := extensionDownloadLog(ctx, c) - if err != nil { - t.Logf("[logs] baseline_error=%v", err) - return "" - } - return apiLog -} - -func waitForExtensionDownload(t *testing.T, ctx context.Context, c *TestContainer, baseline string, timeout time.Duration) { - t.Helper() - deadline := time.Now().Add(timeout) - var lastLog string - var lastErr error - for { - apiLog, err := extensionDownloadLog(ctx, c) - lastLog, lastErr = extensionDownloadLogSince(apiLog, baseline), err - if err == nil && extensionDownloadObserved(lastLog) { - t.Log("[logs] Chrome made GET requests to fetch the enterprise extension") - checkExtensionDownloadLogs(t, ctx, c) - return - } - if time.Now().After(deadline) { - require.NoError(t, lastErr, "extension download was not observed within %s; last_log=%s", timeout, lastLog) - require.True(t, extensionDownloadObserved(lastLog), "extension download was not observed within %s", timeout) - return - } - select { - case <-ctx.Done(): - require.NoError(t, ctx.Err(), "context cancelled waiting for extension download") - return - case <-time.After(1 * time.Second): - } - } -} - -func extensionDownloadLog(ctx context.Context, c *TestContainer) (string, error) { - return execCombinedOutputWithClient(ctx, c, "cat", []string{"/var/log/supervisord/kernel-images-api"}) -} - -func extensionDownloadLogSince(apiLog, baseline string) string { - if baseline != "" && strings.HasPrefix(apiLog, baseline) { - return apiLog[len(baseline):] - } - return apiLog -} - -func extensionDownloadObserved(apiLog string) bool { - var sawUpdateXML, sawCRX bool - for _, line := range strings.Split(apiLog, "\n") { - if !strings.Contains(line, "GET") || !strings.Contains(line, "enterprise-test") { - continue - } - if strings.Contains(line, "update.xml") { - sawUpdateXML = true - } - if strings.Contains(line, ".crx") { - sawCRX = true - } - } - return sawUpdateXML && sawCRX -} - -func TestExtensionDownloadObservedRequiresUpdateXMLAndCRX(t *testing.T) { - t.Parallel() - - require.False(t, extensionDownloadObserved("")) - require.False(t, extensionDownloadObserved(`GET http://127.0.0.1/extensions/enterprise-test/update.xml HTTP/1.1`)) - require.False(t, extensionDownloadObserved(`GET http://127.0.0.1/extensions/enterprise-test/extension.crx HTTP/1.1`)) - require.False(t, extensionDownloadObserved(`GET http://127.0.0.1/extensions/kernel/update.xml HTTP/1.1 -GET http://127.0.0.1/extensions/kernel/extension.crx HTTP/1.1`)) - require.True(t, extensionDownloadObserved(`GET http://127.0.0.1/extensions/enterprise-test/update.xml HTTP/1.1 -GET http://127.0.0.1/extensions/enterprise-test/extension.crx HTTP/1.1`)) -} - -func TestExtensionDownloadLogSince(t *testing.T) { - t.Parallel() - - baseline := "line 1\nline 2\n" - require.Equal(t, "line 3\n", extensionDownloadLogSince(baseline+"line 3\n", baseline)) - require.Equal(t, "line 3\n", extensionDownloadLogSince("line 3\n", baseline)) - require.Equal(t, "line 3\n", extensionDownloadLogSince("line 3\n", "")) -} - func TestNextExtensionInstallPollDelay(t *testing.T) { t.Parallel() diff --git a/server/lib/logger/http.go b/server/lib/logger/http.go new file mode 100644 index 000000000..f6468a37e --- /dev/null +++ b/server/lib/logger/http.go @@ -0,0 +1,97 @@ +package logger + +import ( + "fmt" + "log/slog" + "net/http" + "runtime/debug" + "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" + +// RequestLogger logs one line per request once it completes, at INFO, or WARN +// for a 4xx and ERROR for a 5xx. A request whose handler panics past it, as +// with http.ErrAbortHandler, is logged at ERROR as aborted. It replaces chi's +// middleware.Logger, which writes free-form text. +// +// The path is logged, but never the host or query: the query can carry +// credentials (e.g. a URL passed as a query parameter) and customer file paths. +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() + completed := false + defer func() { + status := ww.Status() + if status == 0 && completed { + status = http.StatusOK + } + level := slog.LevelInfo + switch { + case !completed || status >= 500: + level = slog.LevelError + case status >= 400: + level = slog.LevelWarn + } + elapsed := time.Since(start) + args := []any{"path", r.URL.Path, "bytes", ww.BytesWritten()} + if id := chiMiddleware.GetReqID(r.Context()); id != "" { + args = append(args, "request_id", id) + } + attrs := []any{ + "http.request.method", r.Method, + "duration_ms", elapsed.Milliseconds(), + } + if status != 0 { + attrs = append(attrs, "http.response.status_code", status) + } + if !completed { + attrs = append(attrs, "error.type", "aborted") + } + 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) + completed = true + }) + } +} + +// 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) + } + // The panic value is free-form, so only its Go type is indexed. + log.ErrorContext(r.Context(), "panic", "panic", fmt.Sprint(rvr), "stack", string(debug.Stack()), + slog.Group(AttrsKey, "exception.type", fmt.Sprintf("%T", rvr))) + 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..db230abe2 --- /dev/null +++ b/server/lib/logger/http_test.go @@ -0,0 +1,155 @@ +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, "http://secret-host.example/process/abc?url=https://user:pass@site.example/x", nil) + req.Header.Set(chiMiddleware.RequestIDHeader, "hypeman/abc-1") + r.ServeHTTP(httptest.NewRecorder(), req) + + for _, leak := range []string{"secret-host", "user:pass", "site.example", "url="} { + assert.NotContains(t, buf.String(), leak) + } + 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, "hypeman/abc-1", line["request_id"]) + assert.Equal(t, "/process/abc", line["path"]) + 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, "error.type") + assert.NotContains(t, attrs, "path") + } +} + +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.NotContains(t, line, "request_id") + attrs := line[AttrsKey].(map[string]any) + assert.EqualValues(t, http.StatusOK, attrs["http.response.status_code"]) + assert.NotContains(t, attrs, "http.route") +} + +func TestRequestLoggerAborted(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(http.ErrAbortHandler) + }))) + assert.PanicsWithValue(t, http.ErrAbortHandler, func() { + h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil)) + }) + + lines := decodeLines(t, &buf) + require.Len(t, lines, 1) + assert.Equal(t, "ERROR", lines[0]["level"]) + attrs := lines[0][AttrsKey].(map[string]any) + assert.Equal(t, "aborted", attrs["error.type"]) + assert.NotContains(t, attrs, "http.response.status_code") +} + +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("token=secret " + 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, "token=secret "+strings.Repeat("é", 300), panicLine["panic"]) + assert.Contains(t, panicLine["stack"], "TestRecoverer") + assert.Equal(t, map[string]any{"exception.type": "string"}, panicLine[AttrsKey]) + assert.Equal(t, "ERROR", requestLine["level"]) + assert.EqualValues(t, http.StatusInternalServerError, requestLine[AttrsKey].(map[string]any)["http.response.status_code"]) +} + +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()) +}