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/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()
 

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)
+		})
+	}
+}