From 766fd5cc26fde6fdd8743dd675f0bcacb535d03e Mon Sep 17 00:00:00 2001 From: Antoine Toussaint <312536060+antoinetoussaint-byte@users.noreply.github.com> Date: Wed, 21 Oct 2026 12:04:28 -0400 Subject: [PATCH] fix(runtime,builder): health probes are not access-log traffic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A kubelet asks /healthz and /readyz every few seconds for the life of a pod and uvicorn's access log wrote one line per answer — 180 lines per pod every ten minutes on a cell, all "200 OK", shipped to the telemetry store as if they were requests. The agent now 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 and copied into the image by the builder. A service that configures its own logging is untouched; every non-probe line is written exactly as before. Co-Authored-By: Claude Fable 5.1 --- builder.go | 5 ++ codefly_uvicorn_logging.py | 18 +++++ runtime.go | 8 ++- start_request_test.go | 4 +- templates/builder/Dockerfile.tmpl | 7 +- templates/grpc/code/.gitignore.tmpl | 3 + uvicorn-log-config.json | 54 ++++++++++++++ uvicorn_logging.go | 108 ++++++++++++++++++++++++++++ uvicorn_logging_test.go | 52 ++++++++++++++ 9 files changed, 255 insertions(+), 4 deletions(-) create mode 100644 codefly_uvicorn_logging.py create mode 100644 uvicorn-log-config.json create mode 100644 uvicorn_logging.go create mode 100644 uvicorn_logging_test.go diff --git a/builder.go b/builder.go index 032be2f..63e1384 100644 --- a/builder.go +++ b/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 diff --git a/codefly_uvicorn_logging.py b/codefly_uvicorn_logging.py new file mode 100644 index 0000000..1721cf0 --- /dev/null +++ b/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 diff --git a/runtime.go b/runtime.go index 44d53ad..988a957 100644 --- a/runtime.go +++ b/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") } diff --git a/start_request_test.go b/start_request_test.go index e826cd2..ed65d5f 100644 --- a/start_request_test.go +++ b/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)) } diff --git a/templates/builder/Dockerfile.tmpl b/templates/builder/Dockerfile.tmpl index 651778d..d32b544 100644 --- a/templates/builder/Dockerfile.tmpl +++ b/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"] diff --git a/templates/grpc/code/.gitignore.tmpl b/templates/grpc/code/.gitignore.tmpl index eda71de..a4e5d14 100644 --- a/templates/grpc/code/.gitignore.tmpl +++ b/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 diff --git a/uvicorn-log-config.json b/uvicorn-log-config.json new file mode 100644 index 0000000..e761a8b --- /dev/null +++ b/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 +} diff --git a/uvicorn_logging.go b/uvicorn_logging.go new file mode 100644 index 0000000..8ed85db --- /dev/null +++ b/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 +} diff --git a/uvicorn_logging_test.go b/uvicorn_logging_test.go new file mode 100644 index 0000000..269fafa --- /dev/null +++ b/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)) +}