From 5a674283fcbd844ccd2767c55ec1db0ae9e81342 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Thu, 13 Aug 2026 11:17:53 +0530 Subject: [PATCH 01/10] Tag component logs at the producer so JSON log output stays parseable MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The gateway-runtime container runs Envoy, the policy engine and the Python executor on one stdout, and the entrypoint wrapped each process's stdout and stderr in a shell loop that prepended a component tag ([rtr]/[pol]/[pye]). That loop is a blind line filter running outside the processes, so it could not tell prose from a machine-destined JSON record and stamped both. The policy engine's traffic log is always JSON, so every line arrived as [pol] {"timestamp":"...","correlationId":"...","status":200,...} which jq rejects at column 5, as do Splunk, Fluent Bit and Loki. The same defect hit Envoy's access log under router.access_logs.format = "json" and the policy engine's own logs under policy_engine.logging.format = "json". Move tagging to each producer, where prose and machine records are distinguishable, and stop wrapping stdout: - Envoy: "[rtr] " in the default access-log TextFormat; a "component" field in the default JSONFields (deployer json_fields merge with the defaults). - Policy engine: text handler writes through componentPrefixWriter; JSON mode carries a "component" attribute instead. The traffic-log publisher keeps writing to os.Stdout directly and gains its own "component" field, so tagged prose and untouched JSON share one descriptor. - Python executor: "[pye] " in the logging.Formatter. - plugin_registry.go.tmpl: the generated init() installs a logger before main() does, leaving policy-registration lines untagged. stderr stays wrapped, unconditionally. Nothing writes JSON there (0 of 151 lines in JSON mode) and it carries what bypasses the process loggers — Go runtime dumps, panics, tracebacks, Envoy fatals. Verified at runtime on locally built 1.2.0 images in text mode, JSON mode and with access_logs.enabled = false: zero untagged lines on either stream, all 93 stdout JSON lines parse, no JSON line prefixed, and a forced SIGQUIT stack dump comes out [pol]-tagged. Known limitation: the generated init() logger is fixed to text, since policy_engine.logging.format is unknown until config loads in main(). In JSON mode those bootstrap lines are tagged text a processor can skip. (cherry picked from commit c681a5db6080bb301633c6ab1d541b6f4f80c63b) --- .agents/skills/gateway-debug/SKILL.md | 26 ++-- .../templates/plugin_registry.go.tmpl | 11 +- .../gateway-controller/pkg/config/config.go | 7 +- .../docker-entrypoint-debug.sh | 34 +++-- gateway/gateway-runtime/docker-entrypoint.sh | 45 ++++--- .../policy-engine/cmd/policy-engine/main.go | 39 +++++- .../cmd/policy-engine/main_test.go | 116 ++++++++++++++++++ .../internal/analytics/publishers/log_test.go | 12 ++ .../analytics/publishers/traffic_log_event.go | 6 + .../gateway-runtime/python-executor/main.py | 4 +- 10 files changed, 260 insertions(+), 40 deletions(-) diff --git a/.agents/skills/gateway-debug/SKILL.md b/.agents/skills/gateway-debug/SKILL.md index 92dc1877fb..9663dbf0e6 100644 --- a/.agents/skills/gateway-debug/SKILL.md +++ b/.agents/skills/gateway-debug/SKILL.md @@ -467,13 +467,25 @@ Most bugs surface in logs or config dumps without needing to step through code. | Envoy router (in Docker) — `[rtr]` lines | `cd /gateway && docker compose logs --no-log-prefix gateway-runtime 2>&1 \| grep '^\[rtr\]'` | | Python executor (Option 2B) | `/tmp/python_executor.log` | -> Why the `grep`: the `gateway-runtime` container stamps every log line with -> one of three prefixes — `[rtr]` (Envoy router), `[pol]` (in-container PE, -> still receives xDS pushes even in debug mode), unprefixed (the entrypoint). -> When debugging traffic you only want `[rtr]` — Envoy's access log is where -> each request's status, upstream, and policy verdict actually surface. -> `--no-log-prefix` drops Docker's `gateway-runtime-1 |` per-line prefix so -> the `[rtr]` anchor is at column 0. +> Why the `grep`: human-readable lines in the `gateway-runtime` container carry a +> tag naming the emitting process — `[rtr]` (Envoy router), `[pol]` (in-container +> PE, which still receives xDS pushes even in debug mode), `[pye]` (Python +> executor), `[ent]` (the entrypoint itself). When debugging traffic you only want +> `[rtr]` — Envoy's access log is where each request's status, upstream, and +> policy verdict actually surface. `--no-log-prefix` drops Docker's +> `gateway-runtime-1 |` per-line prefix so the `[rtr]` anchor is at column 0. +> +> Machine-readable stdout is untagged, so `grep '^\['` will not match it: the +> policy engine's JSON traffic log, and Envoy's access log when +> `router.access_logs.format = "json"`, are emitted as bare JSON for log +> processors. They carry the tag as a field instead — `"component":"rtr"` for +> Envoy, `"component":"pol"` for the policy engine — so match with `jq`: +> `docker compose logs --no-log-prefix gateway-runtime | grep '^{' | jq -c 'select(.correlationId)'` +> +> Tags come from each process's own logger (Envoy `text_format` / `--log-format`, +> the PE's `slog` handler, the executor's `logging.Formatter`). The entrypoint tags +> only **stderr** — that is where panics, tracebacks and fatals appear, because +> they bypass those loggers. **Controller log lines** carry `correlation_id=` — grep on it to follow one request end-to-end across handler → service → xDS push: diff --git a/gateway/gateway-builder/templates/plugin_registry.go.tmpl b/gateway/gateway-builder/templates/plugin_registry.go.tmpl index 3b37311d0a..49a02651f4 100644 --- a/gateway/gateway-builder/templates/plugin_registry.go.tmpl +++ b/gateway/gateway-builder/templates/plugin_registry.go.tmpl @@ -35,9 +35,14 @@ import ( ) func init() { - // Set up text logger early so init() logs match main() logs - slog.SetDefault(slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}))) - + // init() runs before main() installs the configured logger, so set one up here + // with the same tag. Format is fixed to text: policy_engine.logging.format is + // not known until config loads in main(). + slog.SetDefault(slog.New(slog.NewTextHandler( + newComponentPrefixWriter(os.Stdout, logComponentPrefix), + &slog.HandlerOptions{Level: slog.LevelInfo}, + ))) + ctx := context.Background() slog.InfoContext(ctx, "Registering policies from Builder compilation") diff --git a/gateway/gateway-controller/pkg/config/config.go b/gateway/gateway-controller/pkg/config/config.go index 289f358974..4a9e8e3e97 100644 --- a/gateway/gateway-controller/pkg/config/config.go +++ b/gateway/gateway-controller/pkg/config/config.go @@ -943,6 +943,9 @@ func defaultConfig() *Config { Enabled: true, Format: "text", JSONFields: map[string]string{ + // Deployer-supplied json_fields merge into these defaults rather than + // replacing them, so "component" survives unless explicitly overridden. + "component": "rtr", "t": "%START_TIME%", "meth": "%REQ(:METHOD)%", "path": "%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%", @@ -967,7 +970,9 @@ func defaultConfig() *Config { "reqDur": "%REQUEST_DURATION%", "respDur": "%RESPONSE_DURATION%", }, - TextFormat: "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" " + + // "[rtr] " identifies the router on the container's shared stdout; keep it + // when overriding. The JSON variant uses the "component" field instead. + TextFormat: "[rtr] [%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" " + "%REQ(:PATH)% %UPSTREAM_PROTOCOL% %RESPONSE_CODE% %RESPONSE_FLAGS% %RESPONSE_CODE_DETAILS% " + "%CONNECTION_TERMINATION_DETAILS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% " + "%REQUEST_TX_DURATION% %RESPONSE_TX_DURATION% %REQUEST_DURATION% %RESPONSE_DURATION% " + diff --git a/gateway/gateway-runtime/docker-entrypoint-debug.sh b/gateway/gateway-runtime/docker-entrypoint-debug.sh index 72aae6797d..f77b96d252 100644 --- a/gateway/gateway-runtime/docker-entrypoint-debug.sh +++ b/gateway/gateway-runtime/docker-entrypoint-debug.sh @@ -38,6 +38,24 @@ log() { echo "[ent] $(date '+%Y-%m-%d %H:%M:%S') $1" } +prefix_stream() { + local tag="$1" + local line + while IFS= read -r line; do + printf '%s %s\n' "$tag" "$line" + done +} + +# Runs "$@" in the background, tagging its stderr, and sets LAUNCHED_PID. +# stdout is left unwrapped so structured output stays parseable; see +# docker-entrypoint.sh. +LAUNCHED_PID="" +launch_tagged() { + local tag="$1"; shift + "$@" 2> >(prefix_stream "$tag" >&2) & + LAUNCHED_PID=$! +} + # Parse process-specific args from command line. # Uses dot (.) as the prefix separator (e.g. --rtr.flag, --pol.flag) because no # standard CLI flag contains a dot, making prefix detection unambiguous. @@ -221,13 +239,11 @@ trap shutdown SIGTERM SIGINT SIGQUIT # Start Policy Engine under dlv for remote debugging (port 2346) log "Starting Policy Engine under dlv (listening on :2346, headless)..." -/usr/local/bin/dlv exec /app/policy-engine \ +launch_tagged "[pol]" /usr/local/bin/dlv exec /app/policy-engine \ --listen=:2346 --headless=true \ --api-version=2 --accept-multiclient -- \ - -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" \ - > >(while IFS= read -r line; do echo "[pol] $line"; done) \ - 2> >(while IFS= read -r line; do echo "[pol] $line" >&2; done) & -PE_PID=$! + -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" +PE_PID=$LAUNCHED_PID log "Policy Engine (dlv) started (PID $PE_PID)" # Wait for Policy Engine to create the socket (with timeout) @@ -261,15 +277,13 @@ log "Policy Engine socket ready: ${POLICY_ENGINE_SOCKET}" # Start Envoy (Router) with [rtr] log prefix log "Starting Envoy..." -/usr/local/bin/envoy \ +launch_tagged "[rtr]" /usr/local/bin/envoy \ -c /etc/envoy/envoy.yaml \ --config-yaml "${CONFIG_OVERRIDE}" \ --log-level "${LOG_LEVEL}" \ --concurrency "${ROUTER_CONCURRENCY}" \ - "${ROUTER_ARGS[@]}" \ - > >(while IFS= read -r line; do echo "[rtr] $line"; done) \ - 2> >(while IFS= read -r line; do echo "[rtr] $line" >&2; done) & -ENVOY_PID=$! + "${ROUTER_ARGS[@]}" +ENVOY_PID=$LAUNCHED_PID log "Envoy started (PID $ENVOY_PID)" log "Gateway Runtime running (DEBUG) - Policy Engine/dlv (PID $PE_PID), Envoy (PID $ENVOY_PID)" diff --git a/gateway/gateway-runtime/docker-entrypoint.sh b/gateway/gateway-runtime/docker-entrypoint.sh index 5804c335dc..eeaecc0753 100644 --- a/gateway/gateway-runtime/docker-entrypoint.sh +++ b/gateway/gateway-runtime/docker-entrypoint.sh @@ -41,6 +41,27 @@ log() { echo "[ent] $(date '+%Y-%m-%d %H:%M:%S') $1" } +prefix_stream() { + local tag="$1" + local line + while IFS= read -r line; do + printf '%s %s\n' "$tag" "$line" + done +} + +# Runs "$@" in the background, tagging its stderr, and sets LAUNCHED_PID. +# +# stdout is not wrapped: it carries structured JSON (access and traffic logs) +# that a line prefix would make unparseable, and each process tags its own stdout +# lines. stderr is wrapped because panics, tracebacks and fatals bypass the +# process loggers. +LAUNCHED_PID="" +launch_tagged() { + local tag="$1"; shift + "$@" 2> >(prefix_stream "$tag" >&2) & + LAUNCHED_PID=$! +} + # Parse process-specific args from command line. # Uses dot (.) as the prefix separator (e.g. --rtr.flag, --pol.flag, --py.flag) because no # standard CLI flag contains a dot, making prefix detection unambiguous. @@ -271,10 +292,8 @@ trap shutdown SIGTERM SIGINT SIGQUIT if [ -f /app/python-executor/python_policy_registry.py ]; then log "Starting Python Executor..." unset PYTHON_EXECUTOR_LISTEN - python3 /app/python-executor/main.py --listen "${PYTHON_EXECUTOR_SOCKET}" "${PY_ARGS[@]}" \ - > >(while IFS= read -r line; do echo "[pye] $line"; done) \ - 2> >(while IFS= read -r line; do echo "[pye] $line" >&2; done) & - PY_PID=$! + launch_tagged "[pye]" python3 /app/python-executor/main.py --listen "${PYTHON_EXECUTOR_SOCKET}" "${PY_ARGS[@]}" + PY_PID=$LAUNCHED_PID log "Python Executor started (PID $PY_PID)" # Wait for Python socket @@ -298,12 +317,10 @@ else log "No Python policies detected, skipping Python Executor" fi -# Start Policy Engine with [pol] log prefix +# Start Policy Engine log "Starting Policy Engine..." -/app/policy-engine -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" \ - > >(while IFS= read -r line; do echo "[pol] $line"; done) \ - 2> >(while IFS= read -r line; do echo "[pol] $line" >&2; done) & -PE_PID=$! +launch_tagged "[pol]" /app/policy-engine -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" +PE_PID=$LAUNCHED_PID log "Policy Engine started (PID $PE_PID)" # Wait for Policy Engine to create the socket (with timeout) @@ -330,17 +347,15 @@ while [ ! -S "${POLICY_ENGINE_SOCKET}" ]; do done log "Policy Engine socket ready: ${POLICY_ENGINE_SOCKET}" -# Start Envoy (Router) with [rtr] log prefix +# Start Envoy (Router) log "Starting Envoy..." -/usr/local/bin/envoy \ +launch_tagged "[rtr]" /usr/local/bin/envoy \ -c /etc/envoy/envoy.yaml \ --config-yaml "${CONFIG_OVERRIDE}" \ --log-level "${LOG_LEVEL}" \ --concurrency "${ROUTER_CONCURRENCY}" \ - "${ROUTER_ARGS[@]}" \ - > >(while IFS= read -r line; do echo "[rtr] $line"; done) \ - 2> >(while IFS= read -r line; do echo "[rtr] $line" >&2; done) & -ENVOY_PID=$! + "${ROUTER_ARGS[@]}" +ENVOY_PID=$LAUNCHED_PID log "Envoy started (PID $ENVOY_PID)" log "Gateway Runtime running" diff --git a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main.go b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main.go index 9978f14ae8..a333d61031 100644 --- a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main.go +++ b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main.go @@ -22,6 +22,7 @@ import ( "context" "flag" "fmt" + "io" "log/slog" "net" "os" @@ -393,16 +394,50 @@ func setupLogger(cfg *config.Config) *slog.Logger { opts := &slog.HandlerOptions{Level: level} + // Tagging is per logger, never process-wide on stdout: the traffic-log + // publisher writes bare JSON to os.Stdout on the same descriptor, and a + // process-wide prefix would corrupt it. var handler slog.Handler if cfg.PolicyEngine.Logging.Format == "json" { handler = slog.NewJSONHandler(os.Stdout, opts) - } else { - handler = slog.NewTextHandler(os.Stdout, opts) + return slog.New(handler).With(slog.String(logComponentField, logComponentValue)) } + handler = slog.NewTextHandler(newComponentPrefixWriter(os.Stdout, logComponentPrefix), opts) return slog.New(handler) } +const ( + logComponentPrefix = "[pol] " + logComponentField = "component" + logComponentValue = "pol" +) + +// componentPrefixWriter prepends a tag to every write. slog emits one complete +// record per Write, so this yields one tag per line. slog serializes writes, so +// no lock is needed here. +type componentPrefixWriter struct { + w io.Writer + prefix []byte +} + +func newComponentPrefixWriter(w io.Writer, prefix string) *componentPrefixWriter { + return &componentPrefixWriter{w: w, prefix: []byte(prefix)} +} + +// Write emits the tag and p in one underlying Write so another writer sharing +// the descriptor cannot interleave between them. The returned count excludes +// the tag, which is framing rather than bytes consumed from the caller. +func (c *componentPrefixWriter) Write(p []byte) (int, error) { + buf := make([]byte, 0, len(c.prefix)+len(p)) + buf = append(buf, c.prefix...) + buf = append(buf, p...) + if _, err := c.w.Write(buf); err != nil { + return 0, err + } + return len(p), nil +} + // initializeXDSClient initializes and starts the xDS client func initializeXDSClient(ctx context.Context, cfg *config.Config, serverAddr string, k *kernel.Kernel, reg *registry.PolicyRegistry) (*xdsclient.Client, error) { slog.InfoContext(ctx, "Initializing xDS client", diff --git a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go index 1069701ac4..c00feaeaf5 100644 --- a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go +++ b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go @@ -19,10 +19,14 @@ package main import ( + "bytes" "context" + "encoding/json" + "errors" "log/slog" "os" "path/filepath" + "strings" "testing" "time" @@ -331,3 +335,115 @@ func TestInitializeXDSClient_ValidConfig(t *testing.T) { // Note: Not calling Stop/Wait due to potential issues with context in test environment // The client will be cleaned up when the test exits } + +// ============================================================================= +// componentPrefixWriter Tests +// ============================================================================= + +func TestComponentPrefixWriter_PrefixesEachWrite(t *testing.T) { + var buf bytes.Buffer + w := newComponentPrefixWriter(&buf, "[pol] ") + + n, err := w.Write([]byte("time=... level=INFO msg=hello\n")) + + require.NoError(t, err) + // n must equal len(p); io.Writer callers treat any other count as a failed + // write. + assert.Equal(t, len("time=... level=INFO msg=hello\n"), n) + assert.Equal(t, "[pol] time=... level=INFO msg=hello\n", buf.String()) +} + +func TestComponentPrefixWriter_OneUnderlyingWritePerRecord(t *testing.T) { + counting := &countingWriter{} + w := newComponentPrefixWriter(counting, "[pol] ") + + _, err := w.Write([]byte("first\n")) + require.NoError(t, err) + _, err = w.Write([]byte("second\n")) + require.NoError(t, err) + + // One underlying write per record, so another writer on the same descriptor + // cannot interleave between tag and line. + assert.Equal(t, 2, counting.writes) + assert.Equal(t, "[pol] first\n[pol] second\n", counting.buf.String()) +} + +func TestComponentPrefixWriter_PropagatesError(t *testing.T) { + w := newComponentPrefixWriter(failingWriter{}, "[pol] ") + + n, err := w.Write([]byte("boom\n")) + + require.Error(t, err) + assert.Zero(t, n) +} + +func TestSetupLogger_TextFormatIsComponentTagged(t *testing.T) { + cfg := &config.Config{ + PolicyEngine: config.PolicyEngine{ + Logging: config.LoggingConfig{Level: "info", Format: "text"}, + }, + } + + out := captureStdout(t, func() { + setupLogger(cfg).Info("hello") + }) + + assert.True(t, strings.HasPrefix(out, "[pol] "), "text log line must be [pol]-tagged, got: %q", out) + assert.Contains(t, out, "msg=hello") +} + +func TestSetupLogger_JSONFormatCarriesComponentField(t *testing.T) { + cfg := &config.Config{ + PolicyEngine: config.PolicyEngine{ + Logging: config.LoggingConfig{Level: "info", Format: "json"}, + }, + } + + out := captureStdout(t, func() { + setupLogger(cfg).Info("hello") + }) + + assert.False(t, strings.HasPrefix(out, "[pol] "), "JSON log line must not be text-prefixed, got: %q", out) + + var rec map[string]any + require.NoError(t, json.Unmarshal([]byte(strings.TrimSpace(out)), &rec), "JSON log line must parse, got: %q", out) + assert.Equal(t, "pol", rec["component"]) + assert.Equal(t, "hello", rec["msg"]) +} + +type countingWriter struct { + buf bytes.Buffer + writes int +} + +func (c *countingWriter) Write(p []byte) (int, error) { + c.writes++ + return c.buf.Write(p) +} + +type failingWriter struct{} + +func (failingWriter) Write([]byte) (int, error) { + return 0, errors.New("write failed") +} + +// captureStdout redirects os.Stdout for the duration of fn. setupLogger binds to +// os.Stdout at construction, so the swap must precede the call. +func captureStdout(t *testing.T, fn func()) string { + t.Helper() + + r, w, err := os.Pipe() + require.NoError(t, err) + + orig := os.Stdout + os.Stdout = w + defer func() { os.Stdout = orig }() + + fn() + require.NoError(t, w.Close()) + + var buf bytes.Buffer + _, err = buf.ReadFrom(r) + require.NoError(t, err) + return buf.String() +} diff --git a/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/log_test.go b/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/log_test.go index 21d28d54a2..2ef7cf68ff 100644 --- a/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/log_test.go +++ b/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/log_test.go @@ -708,3 +708,15 @@ func TestLog_Publish_TopLevelFieldsPresent(t *testing.T) { assert.Equal(t, "192.168.1.1", client["ip"]) assert.Equal(t, "test-agent", client["userAgent"]) } + +func TestLog_Publish_CarriesComponentField(t *testing.T) { + l, read := newLogToFile(t, bothFlowsConfig()) + + l.Publish(createBaseEvent()) + + out := read() + assert.True(t, strings.HasPrefix(out, "{"), "traffic-log line must start with '{', got: %q", out) + + decoded := decodeLine(t, out) + assert.Equal(t, "pol", decoded["component"]) +} diff --git a/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/traffic_log_event.go b/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/traffic_log_event.go index 389a49953b..fa710a0858 100644 --- a/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/traffic_log_event.go +++ b/gateway/gateway-runtime/policy-engine/internal/analytics/publishers/traffic_log_event.go @@ -24,6 +24,8 @@ import ( // trafficLogTimestampFormat is RFC 3339 with millisecond precision. const trafficLogTimestampFormat = "2006-01-02T15:04:05.000Z07:00" +const trafficLogComponent = "pol" + // TrafficLogEvent is the JSON shape written to stdout by the Log publisher. // It is intentionally separate from dto.Event (shaped for Moesif) so its field // names, schema, and presence rules can evolve independently. All string fields @@ -32,6 +34,9 @@ const trafficLogTimestampFormat = "2006-01-02T15:04:05.000Z07:00" // entirely, rather than emitted as "{}") when every one of their own fields // resolves to its zero value — see toTrafficLogEvent. type TrafficLogEvent struct { + // Component names the emitting process, not the record type: the policy + // engine's application logs carry the same value. + Component string `json:"component,omitempty"` Timestamp string `json:"timestamp,omitempty"` CorrelationID string `json:"correlationId,omitempty"` Status int `json:"status,omitempty"` @@ -89,6 +94,7 @@ type TrafficLogClient struct { // masking, and payload truncation. func (l *Log) toTrafficLogEvent(event *dto.Event, dir *dto.TrafficLogDirective) *TrafficLogEvent { tl := &TrafficLogEvent{ + Component: trafficLogComponent, Status: event.ProxyResponseCode, Latencies: event.TrafficLogLatencies, } diff --git a/gateway/gateway-runtime/python-executor/main.py b/gateway/gateway-runtime/python-executor/main.py index 36c230a2be..bada53ddfe 100644 --- a/gateway/gateway-runtime/python-executor/main.py +++ b/gateway/gateway-runtime/python-executor/main.py @@ -121,9 +121,9 @@ def setup_logging(): handler = logging.StreamHandler(sys.stdout) handler.setLevel(level) - # Simple format with [pye] prefix for the entrypoint to identify + # [pye] identifies this process on the container's shared stdout. formatter = logging.Formatter( - fmt='%(asctime)s [%(levelname)s] %(name)s: %(message)s', + fmt='[pye] %(asctime)s [%(levelname)s] %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S' ) handler.setFormatter(formatter) From 4c3c9f0fe76f9445bc35e88f82c43cbe5385970b Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Thu, 13 Aug 2026 11:39:07 +0530 Subject: [PATCH 02/10] Drop the entrypoint helper, delete only the stdout wrapper MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The previous commit extracted the six duplicated prefixing loops into a shared launch_tagged helper. That is a refactor of pre-existing duplication rather than part of this fix, and it moved PID capture behind an out-parameter — PIDs the shutdown trap and the socket-wait liveness checks depend on. Delete just the stdout redirection at each launch site instead, leaving the stderr loops, $! capture and echo formatting exactly as they were. Five removed lines and one comment, with the same observable behaviour. (cherry picked from commit e5ec0ea7a06c34b469159acbd6311193a69eacd0) --- .../docker-entrypoint-debug.sh | 32 ++++--------- gateway/gateway-runtime/docker-entrypoint.sh | 45 +++++++------------ 2 files changed, 23 insertions(+), 54 deletions(-) diff --git a/gateway/gateway-runtime/docker-entrypoint-debug.sh b/gateway/gateway-runtime/docker-entrypoint-debug.sh index f77b96d252..17e2ce6e0f 100644 --- a/gateway/gateway-runtime/docker-entrypoint-debug.sh +++ b/gateway/gateway-runtime/docker-entrypoint-debug.sh @@ -38,24 +38,6 @@ log() { echo "[ent] $(date '+%Y-%m-%d %H:%M:%S') $1" } -prefix_stream() { - local tag="$1" - local line - while IFS= read -r line; do - printf '%s %s\n' "$tag" "$line" - done -} - -# Runs "$@" in the background, tagging its stderr, and sets LAUNCHED_PID. -# stdout is left unwrapped so structured output stays parseable; see -# docker-entrypoint.sh. -LAUNCHED_PID="" -launch_tagged() { - local tag="$1"; shift - "$@" 2> >(prefix_stream "$tag" >&2) & - LAUNCHED_PID=$! -} - # Parse process-specific args from command line. # Uses dot (.) as the prefix separator (e.g. --rtr.flag, --pol.flag) because no # standard CLI flag contains a dot, making prefix detection unambiguous. @@ -239,11 +221,12 @@ trap shutdown SIGTERM SIGINT SIGQUIT # Start Policy Engine under dlv for remote debugging (port 2346) log "Starting Policy Engine under dlv (listening on :2346, headless)..." -launch_tagged "[pol]" /usr/local/bin/dlv exec /app/policy-engine \ +/usr/local/bin/dlv exec /app/policy-engine \ --listen=:2346 --headless=true \ --api-version=2 --accept-multiclient -- \ - -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" -PE_PID=$LAUNCHED_PID + -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" \ + 2> >(while IFS= read -r line; do echo "[pol] $line" >&2; done) & +PE_PID=$! log "Policy Engine (dlv) started (PID $PE_PID)" # Wait for Policy Engine to create the socket (with timeout) @@ -277,13 +260,14 @@ log "Policy Engine socket ready: ${POLICY_ENGINE_SOCKET}" # Start Envoy (Router) with [rtr] log prefix log "Starting Envoy..." -launch_tagged "[rtr]" /usr/local/bin/envoy \ +/usr/local/bin/envoy \ -c /etc/envoy/envoy.yaml \ --config-yaml "${CONFIG_OVERRIDE}" \ --log-level "${LOG_LEVEL}" \ --concurrency "${ROUTER_CONCURRENCY}" \ - "${ROUTER_ARGS[@]}" -ENVOY_PID=$LAUNCHED_PID + "${ROUTER_ARGS[@]}" \ + 2> >(while IFS= read -r line; do echo "[rtr] $line" >&2; done) & +ENVOY_PID=$! log "Envoy started (PID $ENVOY_PID)" log "Gateway Runtime running (DEBUG) - Policy Engine/dlv (PID $PE_PID), Envoy (PID $ENVOY_PID)" diff --git a/gateway/gateway-runtime/docker-entrypoint.sh b/gateway/gateway-runtime/docker-entrypoint.sh index eeaecc0753..b88d751885 100644 --- a/gateway/gateway-runtime/docker-entrypoint.sh +++ b/gateway/gateway-runtime/docker-entrypoint.sh @@ -41,27 +41,6 @@ log() { echo "[ent] $(date '+%Y-%m-%d %H:%M:%S') $1" } -prefix_stream() { - local tag="$1" - local line - while IFS= read -r line; do - printf '%s %s\n' "$tag" "$line" - done -} - -# Runs "$@" in the background, tagging its stderr, and sets LAUNCHED_PID. -# -# stdout is not wrapped: it carries structured JSON (access and traffic logs) -# that a line prefix would make unparseable, and each process tags its own stdout -# lines. stderr is wrapped because panics, tracebacks and fatals bypass the -# process loggers. -LAUNCHED_PID="" -launch_tagged() { - local tag="$1"; shift - "$@" 2> >(prefix_stream "$tag" >&2) & - LAUNCHED_PID=$! -} - # Parse process-specific args from command line. # Uses dot (.) as the prefix separator (e.g. --rtr.flag, --pol.flag, --py.flag) because no # standard CLI flag contains a dot, making prefix detection unambiguous. @@ -292,8 +271,9 @@ trap shutdown SIGTERM SIGINT SIGQUIT if [ -f /app/python-executor/python_policy_registry.py ]; then log "Starting Python Executor..." unset PYTHON_EXECUTOR_LISTEN - launch_tagged "[pye]" python3 /app/python-executor/main.py --listen "${PYTHON_EXECUTOR_SOCKET}" "${PY_ARGS[@]}" - PY_PID=$LAUNCHED_PID + python3 /app/python-executor/main.py --listen "${PYTHON_EXECUTOR_SOCKET}" "${PY_ARGS[@]}" \ + 2> >(while IFS= read -r line; do echo "[pye] $line" >&2; done) & + PY_PID=$! log "Python Executor started (PID $PY_PID)" # Wait for Python socket @@ -317,10 +297,14 @@ else log "No Python policies detected, skipping Python Executor" fi -# Start Policy Engine +# Start Policy Engine. Only stderr is prefixed: stdout carries the JSON traffic +# log, which a line prefix would make unparseable, and the policy engine tags its +# own stdout lines. stderr keeps the prefix because panics and stack dumps bypass +# its logger. log "Starting Policy Engine..." -launch_tagged "[pol]" /app/policy-engine -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" -PE_PID=$LAUNCHED_PID +/app/policy-engine -xds-server "${PE_XDS_SERVER}" "${PE_ARGS[@]}" \ + 2> >(while IFS= read -r line; do echo "[pol] $line" >&2; done) & +PE_PID=$! log "Policy Engine started (PID $PE_PID)" # Wait for Policy Engine to create the socket (with timeout) @@ -347,15 +331,16 @@ while [ ! -S "${POLICY_ENGINE_SOCKET}" ]; do done log "Policy Engine socket ready: ${POLICY_ENGINE_SOCKET}" -# Start Envoy (Router) +# Start Envoy (Router) with [rtr] log prefix log "Starting Envoy..." -launch_tagged "[rtr]" /usr/local/bin/envoy \ +/usr/local/bin/envoy \ -c /etc/envoy/envoy.yaml \ --config-yaml "${CONFIG_OVERRIDE}" \ --log-level "${LOG_LEVEL}" \ --concurrency "${ROUTER_CONCURRENCY}" \ - "${ROUTER_ARGS[@]}" -ENVOY_PID=$LAUNCHED_PID + "${ROUTER_ARGS[@]}" \ + 2> >(while IFS= read -r line; do echo "[rtr] $line" >&2; done) & +ENVOY_PID=$! log "Envoy started (PID $ENVOY_PID)" log "Gateway Runtime running" From 5045fa17a38895e3984248eb60344e1fdfc9dd4c Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Thu, 13 Aug 2026 12:04:50 +0530 Subject: [PATCH 03/10] Trim the debug-skill note to the claim this change invalidates MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The skill said the container "stamps every log line" and told you to grep '^\[rtr\]'. Machine-readable stdout is no longer stamped, so that recipe now misses the traffic log entirely. Qualify the sentence and state where JSON records went. Drops the earlier version's tour of which producer applies which tag — that is implementation detail already recorded at each code site, and it credited Envoy's tagging to --log-format, which this change does not set. (cherry picked from commit 55dd1035d3bf87c29d4f346f9116965973030b89) --- .agents/skills/gateway-debug/SKILL.md | 28 ++++++++++----------------- 1 file changed, 10 insertions(+), 18 deletions(-) diff --git a/.agents/skills/gateway-debug/SKILL.md b/.agents/skills/gateway-debug/SKILL.md index 9663dbf0e6..552441a47f 100644 --- a/.agents/skills/gateway-debug/SKILL.md +++ b/.agents/skills/gateway-debug/SKILL.md @@ -467,25 +467,17 @@ Most bugs surface in logs or config dumps without needing to step through code. | Envoy router (in Docker) — `[rtr]` lines | `cd /gateway && docker compose logs --no-log-prefix gateway-runtime 2>&1 \| grep '^\[rtr\]'` | | Python executor (Option 2B) | `/tmp/python_executor.log` | -> Why the `grep`: human-readable lines in the `gateway-runtime` container carry a -> tag naming the emitting process — `[rtr]` (Envoy router), `[pol]` (in-container -> PE, which still receives xDS pushes even in debug mode), `[pye]` (Python -> executor), `[ent]` (the entrypoint itself). When debugging traffic you only want -> `[rtr]` — Envoy's access log is where each request's status, upstream, and -> policy verdict actually surface. `--no-log-prefix` drops Docker's -> `gateway-runtime-1 |` per-line prefix so the `[rtr]` anchor is at column 0. +> Why the `grep`: the `gateway-runtime` container stamps every human-readable log +> line with one of three prefixes — `[rtr]` (Envoy router), `[pol]` (in-container PE, +> still receives xDS pushes even in debug mode), unprefixed (the entrypoint). +> When debugging traffic you only want `[rtr]` — Envoy's access log is where +> each request's status, upstream, and policy verdict actually surface. +> `--no-log-prefix` drops Docker's `gateway-runtime-1 |` per-line prefix so +> the `[rtr]` anchor is at column 0. > -> Machine-readable stdout is untagged, so `grep '^\['` will not match it: the -> policy engine's JSON traffic log, and Envoy's access log when -> `router.access_logs.format = "json"`, are emitted as bare JSON for log -> processors. They carry the tag as a field instead — `"component":"rtr"` for -> Envoy, `"component":"pol"` for the policy engine — so match with `jq`: -> `docker compose logs --no-log-prefix gateway-runtime | grep '^{' | jq -c 'select(.correlationId)'` -> -> Tags come from each process's own logger (Envoy `text_format` / `--log-format`, -> the PE's `slog` handler, the executor's `logging.Formatter`). The entrypoint tags -> only **stderr** — that is where panics, tracebacks and fatals appear, because -> they bypass those loggers. +> JSON output on stdout is not prefixed — the policy engine's traffic log, and +> Envoy's access log when `router.access_logs.format = "json"` — so `grep '^\['` +> will not match it. Those records carry a `"component"` field instead. **Controller log lines** carry `correlation_id=` — grep on it to follow one request end-to-end across handler → service → xDS push: From 644b96dadde7045a0e1b49262c24c97451457414 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Tue, 18 Aug 2026 10:08:04 +0530 Subject: [PATCH 04/10] Warn when a custom text access-log format drops the router tag Two review findings. The entrypoint used to prefix the router's whole stdout stream, so a deployer-supplied router.access_logs.text_format still got tagged. Now that only the shipped default carries "[rtr] ", overriding text_format silently loses router attribution on the shared stdout, and validation only checks the format is non-empty. Warn at startup instead of injecting the tag: a format string should render as written, an operator may have dropped the tag deliberately, and detecting "missing" reliably is guesswork. The tag is now a named constant shared by the default and the check, so the two cannot drift. Also close the read end of the pipe in captureStdout, which leaked a descriptor per call. --- gateway/configs/config.toml | 12 +++++-- .../gateway-controller/pkg/config/config.go | 26 +++++++++++++-- .../pkg/config/config_test.go | 33 +++++++++++++++++++ .../cmd/policy-engine/main_test.go | 1 + 4 files changed, 67 insertions(+), 5 deletions(-) diff --git a/gateway/configs/config.toml b/gateway/configs/config.toml index e81a042d7a..e2f5a8cd14 100644 --- a/gateway/configs/config.toml +++ b/gateway/configs/config.toml @@ -1,15 +1,22 @@ [analytics] -enabled = true -enabled_publishers = ["moesif"] +enabled = false +enabled_publishers = [] [analytics.publishers.moesif] application_id = '{{ env "APIP_GW_ANALYTICS_PUBLISHERS_MOESIF_APPLICATION_ID" "" }}' +[traffic_logging] +enabled = true + +[collector] +ignore_path_prefixes = ["/_gateway-health"] + [router] gateway_host = "*" [router.access_logs] enabled = true +format = "json" [controller.server] gateway_id = '{{ env "APIP_GW_CONTROLLER_SERVER_GATEWAY_ID" "platform-gateway-id" }}' @@ -22,6 +29,7 @@ path = '{{ env "APIP_GW_CONTROLLER_STORAGE_SQLITE_PATH" "./data/gateway.db" }}' [policy_engine.logging] level = "info" +format = "json" [controller.logging] level = '{{ env "APIP_GW_CONTROLLER_LOGGING_LEVEL" "info" }}' diff --git a/gateway/gateway-controller/pkg/config/config.go b/gateway/gateway-controller/pkg/config/config.go index 4a9e8e3e97..100e9e52a6 100644 --- a/gateway/gateway-controller/pkg/config/config.go +++ b/gateway/gateway-controller/pkg/config/config.go @@ -823,6 +823,18 @@ func defaultGRPCEventServerConfig() GRPCEventServerConfig { } // defaultConfig returns a Config struct with default configuration values +// routerLogComponentTag prefixes the router's text access-log lines so they stay +// separable from the policy engine's and the Python executor's output on the +// container's shared stdout. +const routerLogComponentTag = "[rtr] " + +// textAccessLogHasComponentTag reports whether a text access-log format carries +// routerLogComponentTag. A deployer-supplied text_format replaces the default +// outright, so the tag can go missing without anything else noticing. +func textAccessLogHasComponentTag(textFormat string) bool { + return strings.Contains(textFormat, routerLogComponentTag) +} + func defaultConfig() *Config { return &Config{ Controller: Controller{ @@ -970,9 +982,10 @@ func defaultConfig() *Config { "reqDur": "%REQUEST_DURATION%", "respDur": "%RESPONSE_DURATION%", }, - // "[rtr] " identifies the router on the container's shared stdout; keep it - // when overriding. The JSON variant uses the "component" field instead. - TextFormat: "[rtr] [%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" " + + // routerLogComponentTag identifies the router on the container's shared + // stdout; keep it when overriding. The JSON variant uses the "component" + // field instead. + TextFormat: routerLogComponentTag + "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" " + "%REQ(:PATH)% %UPSTREAM_PROTOCOL% %RESPONSE_CODE% %RESPONSE_FLAGS% %RESPONSE_CODE_DETAILS% " + "%CONNECTION_TERMINATION_DETAILS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% " + "%REQUEST_TX_DURATION% %RESPONSE_TX_DURATION% %REQUEST_DURATION% %RESPONSE_DURATION% " + @@ -1326,6 +1339,13 @@ func (c *Config) Validate() error { if c.Router.AccessLogs.TextFormat == "" { return fmt.Errorf("router.access_logs.text_format must be configured when format is 'text'") } + // Warn rather than fail: an operator may have dropped the tag on purpose, + // and refusing to start over a log-formatting choice would be worse than + // the ambiguity it causes. + if !textAccessLogHasComponentTag(c.Router.AccessLogs.TextFormat) { + slog.Warn("router.access_logs.text_format does not contain "+routerLogComponentTag+ + "; router access-log lines will not be attributable on the container's shared stdout") + } } } diff --git a/gateway/gateway-controller/pkg/config/config_test.go b/gateway/gateway-controller/pkg/config/config_test.go index d70567181d..8574b0dfa0 100644 --- a/gateway/gateway-controller/pkg/config/config_test.go +++ b/gateway/gateway-controller/pkg/config/config_test.go @@ -1915,3 +1915,36 @@ func TestConfig_CaseInsensitiveAlgorithm(t *testing.T) { err := cfg.Validate() assert.NoError(t, err, "Algorithm validation should be case insensitive") } + +func TestTextAccessLogHasComponentTag(t *testing.T) { + // A deployer-supplied text_format replaces the default outright, so the router's + // component tag can go missing with nothing else to catch it. + tests := []struct { + name string + textFormat string + want bool + }{ + {"shipped default", defaultConfig().Router.AccessLogs.TextFormat, true}, + {"custom format keeping the tag", "[rtr] %RESPONSE_CODE%\n", true}, + {"custom format dropping the tag", "[%START_TIME%] %RESPONSE_CODE%\n", false}, + {"empty", "", false}, + {"tag without its trailing space is not a match", "[rtr]%RESPONSE_CODE%\n", false}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert.Equal(t, tt.want, textAccessLogHasComponentTag(tt.textFormat)) + }) + } +} + +func TestValidate_CustomTextAccessLogWithoutTagIsNotFatal(t *testing.T) { + // Dropping the tag is a log-formatting choice, not a misconfiguration: it must + // warn, never refuse to start. + cfg := defaultConfig() + cfg.Router.AccessLogs.Enabled = true + cfg.Router.AccessLogs.Format = "text" + cfg.Router.AccessLogs.TextFormat = "[%START_TIME%] %RESPONSE_CODE%\n" + + assert.False(t, textAccessLogHasComponentTag(cfg.Router.AccessLogs.TextFormat)) + assert.NoError(t, cfg.Validate()) +} diff --git a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go index c00feaeaf5..f810570eb6 100644 --- a/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go +++ b/gateway/gateway-runtime/policy-engine/cmd/policy-engine/main_test.go @@ -434,6 +434,7 @@ func captureStdout(t *testing.T, fn func()) string { r, w, err := os.Pipe() require.NoError(t, err) + defer r.Close() orig := os.Stdout os.Stdout = w From daf272a8addefb60eb14458110edfb6942a7a24b Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Tue, 18 Aug 2026 10:19:00 +0530 Subject: [PATCH 05/10] Require the router tag to lead the text access-log format strings.Contains accepted a format such as "[%START_TIME%] [rtr] ...", which renders lines like "[2026-...] [rtr] 200". The tag is present but attribution anchors on it at column 0, so grepping by component still misses those lines and no warning fired. Match with HasPrefix, rename the predicate to say what it now checks, and cover a mid-format tag and a leading space. --- gateway/gateway-controller/pkg/config/config.go | 17 ++++++++++------- .../pkg/config/config_test.go | 10 +++++++--- 2 files changed, 17 insertions(+), 10 deletions(-) diff --git a/gateway/gateway-controller/pkg/config/config.go b/gateway/gateway-controller/pkg/config/config.go index 100e9e52a6..31145516e8 100644 --- a/gateway/gateway-controller/pkg/config/config.go +++ b/gateway/gateway-controller/pkg/config/config.go @@ -828,11 +828,14 @@ func defaultGRPCEventServerConfig() GRPCEventServerConfig { // container's shared stdout. const routerLogComponentTag = "[rtr] " -// textAccessLogHasComponentTag reports whether a text access-log format carries -// routerLogComponentTag. A deployer-supplied text_format replaces the default -// outright, so the tag can go missing without anything else noticing. -func textAccessLogHasComponentTag(textFormat string) bool { - return strings.Contains(textFormat, routerLogComponentTag) +// textAccessLogStartsWithComponentTag reports whether a text access-log format +// opens with routerLogComponentTag. A deployer-supplied text_format replaces the +// default outright, so the tag can go missing without anything else noticing. +// +// The tag has to lead the line, not merely appear in it: attribution works by +// anchoring on it at column 0, so a tag placed mid-format is present but useless. +func textAccessLogStartsWithComponentTag(textFormat string) bool { + return strings.HasPrefix(textFormat, routerLogComponentTag) } func defaultConfig() *Config { @@ -1342,8 +1345,8 @@ func (c *Config) Validate() error { // Warn rather than fail: an operator may have dropped the tag on purpose, // and refusing to start over a log-formatting choice would be worse than // the ambiguity it causes. - if !textAccessLogHasComponentTag(c.Router.AccessLogs.TextFormat) { - slog.Warn("router.access_logs.text_format does not contain "+routerLogComponentTag+ + if !textAccessLogStartsWithComponentTag(c.Router.AccessLogs.TextFormat) { + slog.Warn("router.access_logs.text_format does not start with "+routerLogComponentTag+ "; router access-log lines will not be attributable on the container's shared stdout") } } diff --git a/gateway/gateway-controller/pkg/config/config_test.go b/gateway/gateway-controller/pkg/config/config_test.go index 8574b0dfa0..ab93068749 100644 --- a/gateway/gateway-controller/pkg/config/config_test.go +++ b/gateway/gateway-controller/pkg/config/config_test.go @@ -1916,7 +1916,7 @@ func TestConfig_CaseInsensitiveAlgorithm(t *testing.T) { assert.NoError(t, err, "Algorithm validation should be case insensitive") } -func TestTextAccessLogHasComponentTag(t *testing.T) { +func TestTextAccessLogStartsWithComponentTag(t *testing.T) { // A deployer-supplied text_format replaces the default outright, so the router's // component tag can go missing with nothing else to catch it. tests := []struct { @@ -1929,10 +1929,14 @@ func TestTextAccessLogHasComponentTag(t *testing.T) { {"custom format dropping the tag", "[%START_TIME%] %RESPONSE_CODE%\n", false}, {"empty", "", false}, {"tag without its trailing space is not a match", "[rtr]%RESPONSE_CODE%\n", false}, + // Present but not leading: attribution anchors on the tag at column 0, so a + // line reading "[2026-...] [rtr] 200" is not greppable by component. + {"tag appearing mid-format does not count", "[%START_TIME%] [rtr] %RESPONSE_CODE%\n", false}, + {"leading space before the tag does not count", " [rtr] %RESPONSE_CODE%\n", false}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - assert.Equal(t, tt.want, textAccessLogHasComponentTag(tt.textFormat)) + assert.Equal(t, tt.want, textAccessLogStartsWithComponentTag(tt.textFormat)) }) } } @@ -1945,6 +1949,6 @@ func TestValidate_CustomTextAccessLogWithoutTagIsNotFatal(t *testing.T) { cfg.Router.AccessLogs.Format = "text" cfg.Router.AccessLogs.TextFormat = "[%START_TIME%] %RESPONSE_CODE%\n" - assert.False(t, textAccessLogHasComponentTag(cfg.Router.AccessLogs.TextFormat)) + assert.False(t, textAccessLogStartsWithComponentTag(cfg.Router.AccessLogs.TextFormat)) assert.NoError(t, cfg.Validate()) } From e09f36aab590a8897ceade8fc58b07332bff3a14 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Tue, 18 Aug 2026 10:41:35 +0530 Subject: [PATCH 06/10] Revert gateway/configs/config.toml Local verification scaffolding committed by mistake: it disabled analytics, switched both the access log and policy-engine logging to JSON, and turned traffic logging on. None of that belongs in the shipped defaults. --- gateway/configs/config.toml | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) diff --git a/gateway/configs/config.toml b/gateway/configs/config.toml index e2f5a8cd14..e81a042d7a 100644 --- a/gateway/configs/config.toml +++ b/gateway/configs/config.toml @@ -1,22 +1,15 @@ [analytics] -enabled = false -enabled_publishers = [] +enabled = true +enabled_publishers = ["moesif"] [analytics.publishers.moesif] application_id = '{{ env "APIP_GW_ANALYTICS_PUBLISHERS_MOESIF_APPLICATION_ID" "" }}' -[traffic_logging] -enabled = true - -[collector] -ignore_path_prefixes = ["/_gateway-health"] - [router] gateway_host = "*" [router.access_logs] enabled = true -format = "json" [controller.server] gateway_id = '{{ env "APIP_GW_CONTROLLER_SERVER_GATEWAY_ID" "platform-gateway-id" }}' @@ -29,7 +22,6 @@ path = '{{ env "APIP_GW_CONTROLLER_STORAGE_SQLITE_PATH" "./data/gateway.db" }}' [policy_engine.logging] level = "info" -format = "json" [controller.logging] level = '{{ env "APIP_GW_CONTROLLER_LOGGING_LEVEL" "info" }}' From 09e8035f8aa1dbeb7a929067c478aa919b62b0a8 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Tue, 18 Aug 2026 10:45:32 +0530 Subject: [PATCH 07/10] Restore defaultConfig's doc comment and gofmt the warning The new constant was inserted between defaultConfig's doc comment and its declaration, leaving the comment attached to the constant and the function undocumented. gofmt also wanted spaces around the operators in the multi-line warning string. --- gateway/gateway-controller/pkg/config/config.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/gateway/gateway-controller/pkg/config/config.go b/gateway/gateway-controller/pkg/config/config.go index 31145516e8..0997ef260a 100644 --- a/gateway/gateway-controller/pkg/config/config.go +++ b/gateway/gateway-controller/pkg/config/config.go @@ -822,7 +822,6 @@ func defaultGRPCEventServerConfig() GRPCEventServerConfig { } } -// defaultConfig returns a Config struct with default configuration values // routerLogComponentTag prefixes the router's text access-log lines so they stay // separable from the policy engine's and the Python executor's output on the // container's shared stdout. @@ -838,6 +837,7 @@ func textAccessLogStartsWithComponentTag(textFormat string) bool { return strings.HasPrefix(textFormat, routerLogComponentTag) } +// defaultConfig returns a Config struct with default configuration values func defaultConfig() *Config { return &Config{ Controller: Controller{ @@ -1346,7 +1346,7 @@ func (c *Config) Validate() error { // and refusing to start over a log-formatting choice would be worse than // the ambiguity it causes. if !textAccessLogStartsWithComponentTag(c.Router.AccessLogs.TextFormat) { - slog.Warn("router.access_logs.text_format does not start with "+routerLogComponentTag+ + slog.Warn("router.access_logs.text_format does not start with " + routerLogComponentTag + "; router access-log lines will not be attributable on the container's shared stdout") } } From 5e415ea754aa1fb1dc6b148a106bd763d7185e9a Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Tue, 18 Aug 2026 11:33:38 +0530 Subject: [PATCH 08/10] Document the [pye] prefix in the gateway-debug skill The prefix inventory listed only [rtr] and [pol], so a reader tailing the container would not know what [pye] lines are or when they appear. Note that the Python executor only starts when compiled Python policies are present, and that Option 2B logs to a host file instead. --- .agents/skills/gateway-debug/SKILL.md | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/.agents/skills/gateway-debug/SKILL.md b/.agents/skills/gateway-debug/SKILL.md index 552441a47f..7115f12e60 100644 --- a/.agents/skills/gateway-debug/SKILL.md +++ b/.agents/skills/gateway-debug/SKILL.md @@ -468,12 +468,15 @@ Most bugs surface in logs or config dumps without needing to step through code. | Python executor (Option 2B) | `/tmp/python_executor.log` | > Why the `grep`: the `gateway-runtime` container stamps every human-readable log -> line with one of three prefixes — `[rtr]` (Envoy router), `[pol]` (in-container PE, -> still receives xDS pushes even in debug mode), unprefixed (the entrypoint). +> line with one of these prefixes — `[rtr]` (Envoy router), `[pol]` (in-container PE, +> still receives xDS pushes even in debug mode), `[pye]` (Python executor, started +> only when compiled Python policies are present), unprefixed (the entrypoint). > When debugging traffic you only want `[rtr]` — Envoy's access log is where > each request's status, upstream, and policy verdict actually surface. > `--no-log-prefix` drops Docker's `gateway-runtime-1 |` per-line prefix so -> the `[rtr]` anchor is at column 0. +> the `[rtr]` anchor is at column 0. `[pye]` lines share this same container +> stdout; under Option 2B the executor runs on the host instead and logs to +> `/tmp/python_executor.log` (see the table above). > > JSON output on stdout is not prefixed — the policy engine's traffic log, and > Envoy's access log when `router.access_logs.format = "json"` — so `grep '^\['` From 233794ba399e5fb28e5f9b8ad31d0c788f82a890 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Mon, 24 Aug 2026 10:18:09 +0530 Subject: [PATCH 09/10] Tag every physical log line in the python executor, not just the first logging.Formatter appends exc_text and stack_info after the format string has been applied, so a tag placed in the format string lands on the first line only and the remaining lines of a traceback reached the container's shared stdout unattributable. Tracebacks are exactly when knowing the emitting process matters. Move the tag out of the format string into a Formatter subclass that prefixes each physical line of the fully formatted record. Co-Authored-By: Claude Opus 5 (1M context) --- .../gateway-runtime/python-executor/main.py | 27 +++++- .../python-executor/tests/test_logging.py | 93 +++++++++++++++++++ 2 files changed, 117 insertions(+), 3 deletions(-) create mode 100644 gateway/gateway-runtime/python-executor/tests/test_logging.py diff --git a/gateway/gateway-runtime/python-executor/main.py b/gateway/gateway-runtime/python-executor/main.py index bada53ddfe..e754241837 100644 --- a/gateway/gateway-runtime/python-executor/main.py +++ b/gateway/gateway-runtime/python-executor/main.py @@ -113,6 +113,28 @@ def _resolve_positive_int( LOG_LEVEL = os.environ.get("LOG_LEVEL", "info").upper() +# LOG_COMPONENT_PREFIX identifies this process on the container's shared stdout, +# which it writes to alongside Envoy and the policy engine. +LOG_COMPONENT_PREFIX = '[pye] ' + + +class ComponentPrefixFormatter(logging.Formatter): + """Formatter that prefixes every physical line of a record. + + The prefix cannot live in the format string: logging.Formatter appends + exc_text and stack_info *after* the format string has been applied, so a + tag placed there lands on the first line only and the remaining lines of a + traceback reach stdout unattributable. Attribution has to hold for every + line, since a traceback is exactly when knowing the emitting process matters. + """ + + def format(self, record): + formatted = super().format(record) + return '\n'.join( + LOG_COMPONENT_PREFIX + line for line in formatted.split('\n') + ) + + def setup_logging(): """Configure structured logging.""" level = getattr(logging, LOG_LEVEL, logging.INFO) @@ -121,9 +143,8 @@ def setup_logging(): handler = logging.StreamHandler(sys.stdout) handler.setLevel(level) - # [pye] identifies this process on the container's shared stdout. - formatter = logging.Formatter( - fmt='[pye] %(asctime)s [%(levelname)s] %(name)s: %(message)s', + formatter = ComponentPrefixFormatter( + fmt='%(asctime)s [%(levelname)s] %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S' ) handler.setFormatter(formatter) diff --git a/gateway/gateway-runtime/python-executor/tests/test_logging.py b/gateway/gateway-runtime/python-executor/tests/test_logging.py new file mode 100644 index 0000000000..ea829b39a2 --- /dev/null +++ b/gateway/gateway-runtime/python-executor/tests/test_logging.py @@ -0,0 +1,93 @@ +import io +import logging +import unittest + +from main import ( + ComponentPrefixFormatter, + LOG_COMPONENT_PREFIX, + setup_logging, +) + + +class ComponentPrefixFormatterTest(unittest.TestCase): + """The container multiplexes Envoy, the policy engine and this process onto + one stdout, so every emitted line has to carry the component tag.""" + + def _emit(self, fn): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(ComponentPrefixFormatter( + fmt='%(asctime)s [%(levelname)s] %(name)s: %(message)s', + datefmt='%Y-%m-%d %H:%M:%S')) + logger = logging.getLogger('test.' + fn.__name__) + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + fn(logger) + handler.flush() + return [ln for ln in stream.getvalue().split('\n') if ln] + + def test_single_line_is_tagged(self): + lines = self._emit(lambda log: log.info('started')) + self.assertEqual(1, len(lines)) + self.assertTrue(lines[0].startswith(LOG_COMPONENT_PREFIX)) + + def test_every_traceback_line_is_tagged(self): + def emit(log): + try: + raise ValueError('boom') + except ValueError: + log.exception('policy execution failed') + + lines = self._emit(emit) + # A traceback spans several lines; the point of the formatter is that the + # tag is not limited to the first. + self.assertGreater(len(lines), 2) + for line in lines: + self.assertTrue(line.startswith(LOG_COMPONENT_PREFIX), line) + + def test_every_line_of_a_multiline_message_is_tagged(self): + lines = self._emit(lambda log: log.info('one\ntwo\nthree')) + self.assertEqual(3, len(lines)) + for line in lines: + self.assertTrue(line.startswith(LOG_COMPONENT_PREFIX), line) + + def test_tag_is_not_applied_twice(self): + lines = self._emit(lambda log: log.info('started')) + self.assertFalse( + lines[0].startswith(LOG_COMPONENT_PREFIX + LOG_COMPONENT_PREFIX)) + + +class SetupLoggingWiringTest(unittest.TestCase): + """The tests above exercise the formatter directly; these pin the wiring, so + that reverting to a plain Formatter or moving the tag back into the format + string is caught rather than only the class being covered.""" + + def setUp(self): + root = logging.getLogger() + self._saved = (root.handlers[:], root.level) + + def tearDown(self): + root = logging.getLogger() + root.handlers, root.level = self._saved + + def test_root_handler_uses_the_prefixing_formatter(self): + logging.getLogger().handlers = [] + setup_logging() + + formatters = [h.formatter for h in logging.getLogger().handlers] + self.assertTrue( + any(isinstance(f, ComponentPrefixFormatter) for f in formatters)) + + def test_format_string_does_not_also_carry_the_tag(self): + # Both places applying the tag would emit it twice on the first line. + logging.getLogger().handlers = [] + setup_logging() + + for handler in logging.getLogger().handlers: + fmt = handler.formatter._style._fmt + self.assertNotIn(LOG_COMPONENT_PREFIX.strip(), fmt) + + +if __name__ == '__main__': + unittest.main() From 20aa6a002fa15edb9718b971fe2393b7f4d91af1 Mon Sep 17 00:00:00 2001 From: Tharsanan1 Date: Mon, 24 Aug 2026 10:39:47 +0530 Subject: [PATCH 10/10] Correct the entrypoint's log prefix in the gateway-debug skill The entrypoint's log() has always emitted "[ent] ", in both docker-entrypoint.sh and docker-entrypoint-debug.sh, so describing its output as unprefixed sent readers looking for lines that do not exist. All four processes sharing the container's stdout are prefixed; only JSON records are not. Co-Authored-By: Claude Opus 5 (1M context) --- .agents/skills/gateway-debug/SKILL.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.agents/skills/gateway-debug/SKILL.md b/.agents/skills/gateway-debug/SKILL.md index 7115f12e60..9205d2e1f5 100644 --- a/.agents/skills/gateway-debug/SKILL.md +++ b/.agents/skills/gateway-debug/SKILL.md @@ -470,7 +470,8 @@ Most bugs surface in logs or config dumps without needing to step through code. > Why the `grep`: the `gateway-runtime` container stamps every human-readable log > line with one of these prefixes — `[rtr]` (Envoy router), `[pol]` (in-container PE, > still receives xDS pushes even in debug mode), `[pye]` (Python executor, started -> only when compiled Python policies are present), unprefixed (the entrypoint). +> only when compiled Python policies are present), and `[ent]` (the entrypoint's +> own startup and shutdown messages). > When debugging traffic you only want `[rtr]` — Envoy's access log is where > each request's status, upstream, and policy verdict actually surface. > `--no-log-prefix` drops Docker's `gateway-runtime-1 |` per-line prefix so