Skip to content

Commit 766fd5c

Browse files
fix(runtime,builder): health probes are not access-log traffic
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 <noreply@anthropic.com>
1 parent a0017a2 commit 766fd5c

9 files changed

Lines changed: 255 additions & 4 deletions

‎builder.go‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -259,6 +259,11 @@ func (s *Builder) Build(ctx context.Context, req *builderv0.BuildRequest) (*buil
259259
if err := s.Base.Templates(ctx, docker, services.WithBuilder(builderFS).WithDestination("%s", outputDir)); err != nil {
260260
return s.Base.Builder.BuildError(err)
261261
}
262+
// uvicorn's logging configuration and its filter module, which the
263+
// Dockerfile copies beside the code (uvicorn_logging.go).
264+
if err := writeUvicornLogging(outputDir); err != nil {
265+
return s.Base.Builder.BuildError(err)
266+
}
262267
image := s.DockerImage(dockerRequest).FullName()
263268
if assembled == nil {
264269
// Only the Dockerfile and its ignore were written, and the application's

‎codefly_uvicorn_logging.py‎

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

‎runtime.go‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -596,6 +596,12 @@ func (s *Runtime) Start(ctx context.Context, req *runtimev0.StartRequest) (*runt
596596
return s.Base.Runtime.StartError(s.Wool.NewError("runner environment not initialized (Init must run before Start)"))
597597
}
598598

599+
// The logging configuration uvicorn is started with (uvicorn_logging.go),
600+
// written beside the project so the filter module is importable from the
601+
// working directory uvicorn puts on sys.path.
602+
if err := writeUvicornLogging(s.Service.SourceLocation); err != nil {
603+
return s.Base.Runtime.StartError(err)
604+
}
599605
proc, err := s.runnerEnvironment.NewProcess("uv", uvicornArgs(s.port, s.FastAPI.Settings.HotReload)...)
600606
if err != nil {
601607
return s.Base.Runtime.StartError(err)
@@ -758,7 +764,7 @@ func httpAnswers(ctx context.Context, target string) error {
758764
// makes uvicorn fork a supervisor that re-executes the app on source edits,
759765
// which is not what a service configured without hot reload asked for.
760766
func uvicornArgs(port uint16, hotReload bool) []string {
761-
args := []string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", fmt.Sprintf("%d", port)}
767+
args := []string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", fmt.Sprintf("%d", port), "--log-config", uvicornLogConfigFile}
762768
if hotReload {
763769
args = append(args, "--reload")
764770
}

‎start_request_test.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -467,10 +467,10 @@ func startStatus(t *testing.T, runtime *Runtime) *runtimev0.StartStatus {
467467
// service configured without hot reload never asked for.
468468
func TestUvicornArgsReloadIsConditional(t *testing.T) {
469469
require.Equal(t,
470-
[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080"},
470+
[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json"},
471471
uvicornArgs(8080, false))
472472
require.Equal(t,
473-
[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--reload"},
473+
[]string{"run", "uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json", "--reload"},
474474
uvicornArgs(8080, true))
475475
}
476476

‎templates/builder/Dockerfile.tmpl‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -74,5 +74,10 @@ ENV {{.Key}} {{.Value}}
7474

7575
WORKDIR /app/code
7676

77+
# uvicorn's logging configuration and the filter it names (uvicorn_logging.go):
78+
# health probes are dropped from the access log, everything else is as uvicorn
79+
# writes it. Both files are rendered into the build context by the builder.
80+
COPY --chown=appuser uvicorn-log-config.json codefly_uvicorn_logging.py ./
81+
7782
# Default REST port (overridden by codefly at runtime).
78-
CMD ["uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080"]
83+
CMD ["uvicorn", "src.main:app", "--host", "0.0.0.0", "--port", "8080", "--log-config", "uvicorn-log-config.json"]
Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,2 +1,5 @@
11
# Protobuf + gRPC stubs regenerated by codefly Sync.
22
src/rpc/_generated/
3+
# uvicorn logging written by the python-fastapi agent on every start.
4+
uvicorn-log-config.json
5+
codefly_uvicorn_logging.py

‎uvicorn-log-config.json‎

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,54 @@
1+
{
2+
"disable_existing_loggers": false,
3+
"filters": {
4+
"probes": {
5+
"()": "codefly_uvicorn_logging.ProbeFilter"
6+
}
7+
},
8+
"formatters": {
9+
"access": {
10+
"()": "uvicorn.logging.AccessFormatter",
11+
"fmt": "%(levelprefix)s %(client_addr)s - \"%(request_line)s\" %(status_code)s"
12+
},
13+
"default": {
14+
"()": "uvicorn.logging.DefaultFormatter",
15+
"fmt": "%(levelprefix)s %(message)s",
16+
"use_colors": null
17+
}
18+
},
19+
"handlers": {
20+
"access": {
21+
"class": "logging.StreamHandler",
22+
"filters": [
23+
"probes"
24+
],
25+
"formatter": "access",
26+
"stream": "ext://sys.stdout"
27+
},
28+
"default": {
29+
"class": "logging.StreamHandler",
30+
"formatter": "default",
31+
"stream": "ext://sys.stderr"
32+
}
33+
},
34+
"loggers": {
35+
"uvicorn": {
36+
"handlers": [
37+
"default"
38+
],
39+
"level": "INFO",
40+
"propagate": false
41+
},
42+
"uvicorn.access": {
43+
"handlers": [
44+
"access"
45+
],
46+
"level": "INFO",
47+
"propagate": false
48+
},
49+
"uvicorn.error": {
50+
"level": "INFO"
51+
}
52+
},
53+
"version": 1
54+
}

‎uvicorn_logging.go‎

Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,108 @@
1+
package main
2+
3+
import (
4+
"encoding/json"
5+
"fmt"
6+
"os"
7+
"path/filepath"
8+
)
9+
10+
// Health probes are not traffic. A kubelet asks /healthz and /readyz every
11+
// few seconds for the life of a pod, and uvicorn's access log writes one line
12+
// per answer: on a cell that was 180 lines per pod every ten minutes, all of
13+
// them "200 OK", shipped to the telemetry store as if they were requests. The
14+
// trace of a real request already carries what an access line says; a probe
15+
// hit says nothing anyone reads.
16+
//
17+
// The service is not asked to know this. The agent hands uvicorn a logging
18+
// configuration — uvicorn's own default, with one filter on the access
19+
// handler — and the filter's module, in both places a service runs: written
20+
// beside the project for a native run (`uv run uvicorn` puts the working
21+
// directory on sys.path) and copied into the image by the builder. A service
22+
// that configures its own logging is untouched: --log-config only shapes
23+
// uvicorn's loggers.
24+
25+
// uvicornLogConfigFile and uvicornLoggingModule are the two files, named so a
26+
// service's .gitignore can name them: they are the agent's, regenerated on
27+
// every start, never the service's source.
28+
const (
29+
uvicornLogConfigFile = "uvicorn-log-config.json"
30+
uvicornLoggingModule = "codefly_uvicorn_logging.py"
31+
)
32+
33+
// probePaths is the set a kubelet (and a mesh, and a load balancer) probes.
34+
const probePaths = `^/(healthz|readyz|livez|health|ready|live|ping)$`
35+
36+
// uvicornLoggingModuleSource is the filter: uvicorn's access record carries
37+
// the request as its args (client address, method, path, HTTP version, status
38+
// code), and a probe path is dropped before the handler formats it.
39+
const uvicornLoggingModuleSource = `"""Codefly's uvicorn logging filter. Generated by the python-fastapi agent;
40+
regenerated on every start, so edits here do not survive. Health probes are
41+
not traffic: an access-log line for /healthz or /readyz is dropped before it is
42+
formatted, and every other line is written exactly as uvicorn writes it."""
43+
import logging
44+
import re
45+
46+
PROBE_PATHS = re.compile(r"` + probePaths + `")
47+
48+
49+
class ProbeFilter(logging.Filter):
50+
def filter(self, record: logging.LogRecord) -> bool:
51+
args = record.args
52+
if isinstance(args, tuple) and len(args) >= 3 and isinstance(args[2], str):
53+
path = args[2].split("?", 1)[0]
54+
if PROBE_PATHS.match(path):
55+
return False
56+
return True
57+
`
58+
59+
// uvicornLogConfig is uvicorn's default logging configuration (its
60+
// config.LOGGING_CONFIG) with the probe filter on the access handler. Restated
61+
// rather than merged because --log-config replaces the default whole.
62+
func uvicornLogConfig() map[string]any {
63+
return map[string]any{
64+
"version": 1,
65+
"disable_existing_loggers": false,
66+
"filters": map[string]any{
67+
"probes": map[string]any{"()": "codefly_uvicorn_logging.ProbeFilter"},
68+
},
69+
"formatters": map[string]any{
70+
"default": map[string]any{
71+
"()": "uvicorn.logging.DefaultFormatter",
72+
"fmt": "%(levelprefix)s %(message)s",
73+
"use_colors": nil,
74+
},
75+
"access": map[string]any{
76+
"()": "uvicorn.logging.AccessFormatter",
77+
"fmt": `%(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s`,
78+
},
79+
},
80+
"handlers": map[string]any{
81+
"default": map[string]any{"formatter": "default", "class": "logging.StreamHandler", "stream": "ext://sys.stderr"},
82+
"access": map[string]any{"formatter": "access", "class": "logging.StreamHandler", "stream": "ext://sys.stdout", "filters": []string{"probes"}},
83+
},
84+
"loggers": map[string]any{
85+
"uvicorn": map[string]any{"handlers": []string{"default"}, "level": "INFO", "propagate": false},
86+
"uvicorn.error": map[string]any{"level": "INFO"},
87+
"uvicorn.access": map[string]any{"handlers": []string{"access"}, "level": "INFO", "propagate": false},
88+
},
89+
}
90+
}
91+
92+
// writeUvicornLogging writes the configuration and the filter module into dir,
93+
// the directory uvicorn runs from. Both are rewritten whole on every call.
94+
func writeUvicornLogging(dir string) error {
95+
config, err := json.MarshalIndent(uvicornLogConfig(), "", " ")
96+
if err != nil {
97+
return fmt.Errorf("render uvicorn logging configuration: %w", err)
98+
}
99+
for name, content := range map[string][]byte{
100+
uvicornLogConfigFile: append(config, '\n'),
101+
uvicornLoggingModule: []byte(uvicornLoggingModuleSource),
102+
} {
103+
if err := os.WriteFile(filepath.Join(dir, name), content, 0o644); err != nil {
104+
return fmt.Errorf("write %s: %w", name, err)
105+
}
106+
}
107+
return nil
108+
}

‎uvicorn_logging_test.go‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
package main
2+
3+
import (
4+
"encoding/json"
5+
"os"
6+
"path/filepath"
7+
"regexp"
8+
"testing"
9+
10+
"github.com/stretchr/testify/require"
11+
)
12+
13+
// TestUvicornLoggingDropsProbesAndNothingElse pins the two files the agent
14+
// hands uvicorn: a logging configuration that is uvicorn's own default with
15+
// one filter on the access handler, and the filter module that drops a probe
16+
// path and keeps every other request line.
17+
func TestUvicornLoggingDropsProbesAndNothingElse(t *testing.T) {
18+
dir := t.TempDir()
19+
require.NoError(t, writeUvicornLogging(dir))
20+
21+
raw, err := os.ReadFile(filepath.Join(dir, uvicornLogConfigFile))
22+
require.NoError(t, err)
23+
var config map[string]any
24+
require.NoError(t, json.Unmarshal(raw, &config))
25+
filters := config["filters"].(map[string]any)["probes"].(map[string]any)
26+
require.Equal(t, "codefly_uvicorn_logging.ProbeFilter", filters["()"])
27+
access := config["handlers"].(map[string]any)["access"].(map[string]any)
28+
require.Equal(t, []any{"probes"}, access["filters"], "only the access handler is filtered")
29+
require.NotContains(t, config["handlers"].(map[string]any)["default"], "filters", "uvicorn's own messages are never dropped")
30+
for _, logger := range []string{"uvicorn", "uvicorn.error", "uvicorn.access"} {
31+
require.Contains(t, config["loggers"], logger, "uvicorn's default loggers are restated whole")
32+
}
33+
34+
module, err := os.ReadFile(filepath.Join(dir, uvicornLoggingModule))
35+
require.NoError(t, err)
36+
require.Contains(t, string(module), "class ProbeFilter(logging.Filter)")
37+
38+
probe := regexp.MustCompile(probePaths)
39+
for _, path := range []string{"/healthz", "/readyz", "/livez", "/health", "/ready", "/live", "/ping"} {
40+
require.True(t, probe.MatchString(path), path)
41+
}
42+
for _, path := range []string{"/", "/v1/model/profiles", "/healthz/deep", "/api/health-report", "/pingback"} {
43+
require.False(t, probe.MatchString(path), path)
44+
}
45+
46+
// Rewritten whole on every call: a stale copy never survives an agent upgrade.
47+
require.NoError(t, os.WriteFile(filepath.Join(dir, uvicornLoggingModule), []byte("stale"), 0o644))
48+
require.NoError(t, writeUvicornLogging(dir))
49+
module, err = os.ReadFile(filepath.Join(dir, uvicornLoggingModule))
50+
require.NoError(t, err)
51+
require.NotEqual(t, "stale", string(module))
52+
}

0 commit comments

Comments
 (0)