fix(runtime,builder): health probes are not access-log traffic

builder.go

@@ -259,6 +259,11 @@ func (s *Builder) Build(ctx context.Context, req *builderv0.BuildRequest) (*buil
 	if err := s.Base.Templates(ctx, docker, services.WithBuilder(builderFS).WithDestination("%s", outputDir)); err != nil {
 		return s.Base.Builder.BuildError(err)
 	}
+	// uvicorn's logging configuration and its filter module, which the
+	// Dockerfile copies beside the code (uvicorn_logging.go).
+	if err := writeUvicornLogging(outputDir); err != nil {
+		return s.Base.Builder.BuildError(err)
+	}
 	image := s.DockerImage(dockerRequest).FullName()
 	if assembled == nil {
 		// Only the Dockerfile and its ignore were written, and the application's

codefly_uvicorn_logging.py

@@ -0,0 +1,18 @@
+"""Codefly's uvicorn logging filter. Generated by the python-fastapi agent;
+regenerated on every start, so edits here do not survive. Health probes are
+not traffic: an access-log line for /healthz or /readyz is dropped before it is
+formatted, and every other line is written exactly as uvicorn writes it."""
+import logging
+import re
+
+PROBE_PATHS = re.compile(r"^/(healthz|readyz|livez|health|ready|live|ping)$")
+
+
+class ProbeFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        args = record.args
+        if isinstance(args, tuple) and len(args) >= 3 and isinstance(args[2], str):
+            path = args[2].split("?", 1)[0]
+            if PROBE_PATHS.match(path):
+                return False
+        return True

runtime.go

@@ -596,6 +596,12 @@ func (s *Runtime) Start(ctx context.Context, req *runtimev0.StartRequest) (*runt
 		return s.Base.Runtime.StartError(s.Wool.NewError("runner environment not initialized (Init must run before Start)"))
 	}
 
+	// The logging configuration uvicorn is started with (uvicorn_logging.go),
+	// written beside the project so the filter module is importable from the
+	// working directory uvicorn puts on sys.path.
+	if err := writeUvicornLogging(s.Service.SourceLocation); err != nil {
+		return s.Base.Runtime.StartError(err)
+	}
 	proc, err := s.runnerEnvironment.NewProcess("uv", uvicornArgs(s.port, s.FastAPI.Settings.HotReload)...)
 	if err != nil {
 		return s.Base.Runtime.StartError(err)
@@ -758,7 +764,7 @@ func httpAnswers(ctx context.Context, target string) error {
 // makes uvicorn fork a supervisor that re-executes the app on source edits,
 // which is not what a service configured without hot reload asked for.
 func uvicornArgs(port uint16, hotReload bool) []string {
-	args := []string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", fmt.Sprintf("%d", port)}
+	args := []string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", fmt.Sprintf("%d", port), "--log-config", uvicornLogConfigFile}
 	if hotReload {
 		args = append(args, "--reload")
 	}

start_request_test.go

@@ -467,10 +467,10 @@ func startStatus(t *testing.T, runtime *Runtime) *runtimev0.StartStatus {
 // service configured without hot reload never asked for.
 func TestUvicornArgsReloadIsConditional(t *testing.T) {
 	require.Equal(t,
-		[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080"},
+		[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json"},
 		uvicornArgs(8080, false))
 	require.Equal(t,
-		[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--reload"},
+		[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json", "--reload"},
 		uvicornArgs(8080, true))
 }
 

templates/builder/Dockerfile.tmpl

@@ -74,5 +74,10 @@ ENV {{.Key}} {{.Value}}
 
 WORKDIR /app/code
 
+# uvicorn's logging configuration and the filter it names (uvicorn_logging.go):
+# health probes are dropped from the access log, everything else is as uvicorn
+# writes it. Both files are rendered into the build context by the builder.
+COPY --chown=appuser uvicorn-log-config.json codefly_uvicorn_logging.py ./
+
 # Default REST port (overridden by codefly at runtime).
-CMD ["uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080"]
+CMD ["uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json"]

templates/grpc/code/.gitignore.tmpl

@@ -1,2 +1,5 @@
 # Protobuf + gRPC stubs regenerated by codefly Sync.
 src/rpc/_generated/
+# uvicorn logging written by the python-fastapi agent on every start.
+uvicorn-log-config.json
+codefly_uvicorn_logging.py

uvicorn-log-config.json

@@ -0,0 +1,54 @@
+{
+  "disable_existing_loggers": false,
+  "filters": {
+    "probes": {
+      "()": "codefly_uvicorn_logging.ProbeFilter"
+    }
+  },
+  "formatters": {
+    "access": {
+      "()": "uvicorn.logging.AccessFormatter",
+      "fmt": "%(levelprefix)s %(client_addr)s - \"%(request_line)s\" %(status_code)s"
+    },
+    "default": {
+      "()": "uvicorn.logging.DefaultFormatter",
+      "fmt": "%(levelprefix)s %(message)s",
+      "use_colors": null
+    }
+  },
+  "handlers": {
+    "access": {
+      "class": "logging.StreamHandler",
+      "filters": [
+        "probes"
+      ],
+      "formatter": "access",
+      "stream": "ext://sys.stdout"
+    },
+    "default": {
+      "class": "logging.StreamHandler",
+      "formatter": "default",
+      "stream": "ext://sys.stderr"
+    }
+  },
+  "loggers": {
+    "uvicorn": {
+      "handlers": [
+        "default"
+      ],
+      "level": "INFO",
+      "propagate": false
+    },
+    "uvicorn.access": {
+      "handlers": [
+        "access"
+      ],
+      "level": "INFO",
+      "propagate": false
+    },
+    "uvicorn.error": {
+      "level": "INFO"
+    }
+  },
+  "version": 1
+}

uvicorn_logging.go

@@ -0,0 +1,108 @@
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+	"os"
+	"path/filepath"
+)
+
+// Health probes are not traffic. A kubelet asks /healthz and /readyz every
+// few seconds for the life of a pod, and uvicorn's access log writes one line
+// per answer: on a cell that was 180 lines per pod every ten minutes, all of
+// them "200 OK", shipped to the telemetry store as if they were requests. The
+// trace of a real request already carries what an access line says; a probe
+// hit says nothing anyone reads.
+//
+// The service is not asked to know this. The agent hands uvicorn a logging
+// configuration — uvicorn's own default, with one filter on the access
+// handler — and the filter's module, in both places a service runs: written
+// beside the project for a native run (`uv run uvicorn` puts the working
+// directory on sys.path) and copied into the image by the builder. A service
+// that configures its own logging is untouched: --log-config only shapes
+// uvicorn's loggers.
+
+// uvicornLogConfigFile and uvicornLoggingModule are the two files, named so a
+// service's .gitignore can name them: they are the agent's, regenerated on
+// every start, never the service's source.
+const (
+	uvicornLogConfigFile = "uvicorn-log-config.json"
+	uvicornLoggingModule = "codefly_uvicorn_logging.py"
+)
+
+// probePaths is the set a kubelet (and a mesh, and a load balancer) probes.
+const probePaths = `^/(healthz|readyz|livez|health|ready|live|ping)$`
+
+// uvicornLoggingModuleSource is the filter: uvicorn's access record carries
+// the request as its args (client address, method, path, HTTP version, status
+// code), and a probe path is dropped before the handler formats it.
+const uvicornLoggingModuleSource = `"""Codefly's uvicorn logging filter. Generated by the python-fastapi agent;
+regenerated on every start, so edits here do not survive. Health probes are
+not traffic: an access-log line for /healthz or /readyz is dropped before it is
+formatted, and every other line is written exactly as uvicorn writes it."""
+import logging
+import re
+
+PROBE_PATHS = re.compile(r"` + probePaths + `")
+
+
+class ProbeFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        args = record.args
+        if isinstance(args, tuple) and len(args) >= 3 and isinstance(args[2], str):
+            path = args[2].split("?", 1)[0]
+            if PROBE_PATHS.match(path):
+                return False
+        return True
+`
+
+// uvicornLogConfig is uvicorn's default logging configuration (its
+// config.LOGGING_CONFIG) with the probe filter on the access handler. Restated
+// rather than merged because --log-config replaces the default whole.
+func uvicornLogConfig() map[string]any {
+	return map[string]any{
+		"version":                  1,
+		"disable_existing_loggers": false,
+		"filters": map[string]any{
+			"probes": map[string]any{"()": "codefly_uvicorn_logging.ProbeFilter"},
+		},
+		"formatters": map[string]any{
+			"default": map[string]any{
+				"()":         "uvicorn.logging.DefaultFormatter",
+				"fmt":        "%(levelprefix)s %(message)s",
+				"use_colors": nil,
+			},
+			"access": map[string]any{
+				"()":  "uvicorn.logging.AccessFormatter",
+				"fmt": `%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s`,
+			},
+		},
+		"handlers": map[string]any{
+			"default": map[string]any{"formatter": "default", "class": "logging.StreamHandler", "stream": "ext://sys.stderr"},
+			"access":  map[string]any{"formatter": "access", "class": "logging.StreamHandler", "stream": "ext://sys.stdout", "filters": []string{"probes"}},
+		},
+		"loggers": map[string]any{
+			"uvicorn":        map[string]any{"handlers": []string{"default"}, "level": "INFO", "propagate": false},
+			"uvicorn.error":  map[string]any{"level": "INFO"},
+			"uvicorn.access": map[string]any{"handlers": []string{"access"}, "level": "INFO", "propagate": false},
+		},
+	}
+}
+
+// writeUvicornLogging writes the configuration and the filter module into dir,
+// the directory uvicorn runs from. Both are rewritten whole on every call.
+func writeUvicornLogging(dir string) error {
+	config, err := json.MarshalIndent(uvicornLogConfig(), "", "  ")
+	if err != nil {
+		return fmt.Errorf("render uvicorn logging configuration: %w", err)
+	}
+	for name, content := range map[string][]byte{
+		uvicornLogConfigFile: append(config, '\n'),
+		uvicornLoggingModule: []byte(uvicornLoggingModuleSource),
+	} {
+		if err := os.WriteFile(filepath.Join(dir, name), content, 0o644); err != nil {
+			return fmt.Errorf("write %s: %w", name, err)
+		}
+	}
+	return nil
+}

uvicorn_logging_test.go

@@ -0,0 +1,52 @@
+package main
+
+import (
+	"encoding/json"
+	"os"
+	"path/filepath"
+	"regexp"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+// TestUvicornLoggingDropsProbesAndNothingElse pins the two files the agent
+// hands uvicorn: a logging configuration that is uvicorn's own default with
+// one filter on the access handler, and the filter module that drops a probe
+// path and keeps every other request line.
+func TestUvicornLoggingDropsProbesAndNothingElse(t *testing.T) {
+	dir := t.TempDir()
+	require.NoError(t, writeUvicornLogging(dir))
+
+	raw, err := os.ReadFile(filepath.Join(dir, uvicornLogConfigFile))
+	require.NoError(t, err)
+	var config map[string]any
+	require.NoError(t, json.Unmarshal(raw, &config))
+	filters := config["filters"].(map[string]any)["probes"].(map[string]any)
+	require.Equal(t, "codefly_uvicorn_logging.ProbeFilter", filters["()"])
+	access := config["handlers"].(map[string]any)["access"].(map[string]any)
+	require.Equal(t, []any{"probes"}, access["filters"], "only the access handler is filtered")
+	require.NotContains(t, config["handlers"].(map[string]any)["default"], "filters", "uvicorn's own messages are never dropped")
+	for _, logger := range []string{"uvicorn", "uvicorn.error", "uvicorn.access"} {
+		require.Contains(t, config["loggers"], logger, "uvicorn's default loggers are restated whole")
+	}
+
+	module, err := os.ReadFile(filepath.Join(dir, uvicornLoggingModule))
+	require.NoError(t, err)
+	require.Contains(t, string(module), "class ProbeFilter(logging.Filter)")
+
+	probe := regexp.MustCompile(probePaths)
+	for _, path := range []string{"/healthz", "/readyz", "/livez", "/health", "/ready", "/live", "/ping"} {
+		require.True(t, probe.MatchString(path), path)
+	}
+	for _, path := range []string{"/", "/v1/model/profiles", "/healthz/deep", "/api/health-report", "/pingback"} {
+		require.False(t, probe.MatchString(path), path)
+	}
+
+	// Rewritten whole on every call: a stale copy never survives an agent upgrade.
+	require.NoError(t, os.WriteFile(filepath.Join(dir, uvicornLoggingModule), []byte("stale"), 0o644))
+	require.NoError(t, writeUvicornLogging(dir))
+	module, err = os.ReadFile(filepath.Join(dir, uvicornLoggingModule))
+	require.NoError(t, err)
+	require.NotEqual(t, "stale", string(module))
+}