Operator observability: persist reaped agent logs, expose transcripts, fix service-log filters, demote poll spam - #3566
Conversation
…, fix service-log filters, demote poll spam Closes #3547 (pain points 1, 2, 3, 4, 6; point 5 is tracked by #3241). - New Redis-backed agent_log_store; remove_agent_job snapshots the pod log tail (labels + exit code) before Job deletion, and the container logs route plus get_container_logs MCP tool fall back to the capture for reaped pods. New agent-logs index/read routes. - New get_agent_transcript MCP tool reading the session-state store, with SessionStateStore.list_records and a session-state/index route for discovery. - check_consensus poll-tick observations log at INFO only on state change, DEBUG otherwise; memo resets when consensus completes. - log_filter groups physical lines into logical records (tracebacks stay attached), matches pipeline_id/task_id and [LEVEL] on the console-formatted lines production pods actually emit, and searches patterns across whole records.
There was a problem hiding this comment.
No agent-mode design concerns.
This is operator-observability infrastructure, and it aligns well with the agent-mode guidelines:
- The new MCP tools (
get_agent_transcript, and the persisted-log fallback inget_container_logs) are on-demand pull tools with reasonable caps (linesdefault 200, 1 MiB tail). That's the agent fetching diagnostics when it needs them — the inverse of pre-fetching into a prompt. - The dict returns are MCP tool results consumed by the calling agent (a genuine machine consumer), not human-facing prose, so structured shape is the right interface here.
- Tool/schema descriptions orient rather than prescribe (
_tool_defs.py: "use it to diagnose WHY an agent exited when its pod … [is] already gone"), and the pain-point-3 change inconcurrent_executor.pyis pure log-noise dedup with no agent-mode surface. - No hardcoded model identifiers, no direct Anthropic API calls, and no post-processing of agent output introduced.
— Authored by egg
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
Review: PR #3566 — Operator observability
I reviewed all four fixes systematically (line-by-line, cross-file tracing, and end-to-end verification against the real ConsoleFormatter). This is a well-structured, well-tested change. I found no blocking issues — the core of each feature works in its real execution environment. Approving with a few non-blocking notes below.
Verification I ran
except A, B:(noas) inagent_log_store.py:133andcontainers.py— I initially flagged this as Python 2 syntax, then confirmed it is valid under PEP 758 (Python 3.14) and catches both types.pyproject.tomlpinsrequires-python = ">=3.14"and the Dockerfile ispython:3.14-slim; the unparenthesized form already appears 52× in the tree. Not an issue — noting so future reviewers don't re-flag it.- Console
pipeline_id/levelmatching — reproduced the realConsoleFormatteroutput (use_colors=False,show_source_location=True);_CONSOLE_HEAD_REand_CONSOLE_ID_REextract correctly even with the trailing[path:lineno]suffix. The root-cause analysis in the PR body is accurate and the producer/consumer parity tests are the right call. check_consensusmemo reset — verified theis_completereset is reached on everytracker-truthy path, including the case whereevaluate()is complete on the first tick.
Non-blocking findings
1. _CONSOLE_ID_RE uses leftmost match; the authoritative id is rendered last (log_filter.py).
Structured kwargs (pipeline_id=…) are appended at the end of a console line, but re.search returns the leftmost occurrence. If a log message body — or a quoted kwarg value such as a logged command/URL containing ?pipeline_id=… — contains the token, the filter matches that instead of the record's real id. Consequence is a silent wrong result: false positives (another pipeline's records surface) and, worse, false negatives (the operator's own records are hidden when the leading token belongs to a different id).
I grepped and found no current trigger (the pipeline_id= URLs in mcp_tools/ run in the client process, not the filtered orchestrator pod; _routes_crud.py:325 uses task_id='…' with a quote the regex rejects), so this is latent, not reproducible today — hence non-blocking. Cheap hardening: prefer the last match, or scope the search to the inline key=value region after the message. A regression here would be invisible, so worth closing off.
2. MCP fuzzy fallback can return an unrelated agent's logs (_health.py::_persisted_agent_logs_fallback).
When called with an explicit container_id that misses the exact job-name lookup and agent_role is None, the code falls through to "newest capture overall" and returns it labelled as a different job_name. Realistic path: request logs for a TTL-only-reaped container (no capture) while a sibling was captured via observe-once — the operator asked for job-A and silently gets job-B. The route-level fallback (containers.py) is correctly strict (exact match → 404), so this only affects the MCP tool. Consider returning None (miss) when an explicit container_id was supplied but neither it nor a role matches, rather than guessing newest-overall.
3. Console filtering silently no-ops under ANSI colors (minor).
_CONSOLE_HEAD_RE is anchored and does not tolerate the ANSI escape the formatter wraps the level in when use_colors=True; both the level and (indirectly) id filters then drop every colorized line. Production k8s pods are non-TTY so use_colors=False and are unaffected — noting only in case captured output is ever filtered from a colorized source.
4. Per-removal snapshot adds synchronous k8s I/O to the reap path (minor/perf).
_persist_job_logs_best_effort does a read_namespaced_pod + read_namespaced_pod_log(tail=2000) before every remove_agent_job, including the observe-once sweep and superseded-sibling teardown. It's bounded and correctly best-effort (never blocks removal), but it serializes an extra round-trip per job on the teardown hot path. Acceptable; flagging for awareness.
Strengths
- The
test_log_filter.pytraceback/console classes exercise the realConsoleFormatter(producer/consumer parity), not a hand-rolled fixture — this is exactly the right way to test the filter and would have caught the original JSON-only bug. - Best-effort contract is consistent across both stores (degrade + log, never raise into removal/request paths), and the defensive tests (
_Boomredis, malformed payloads) cover it. - The
known gap(TTL-only reaps) is documented honestly, with the transcript read path as the durable backstop.
— Authored by egg
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
Address review feedback on #3566: - log_filter: prefer the LAST pipeline_id=/task_id= token on a console line (the authoritative structured kwarg is appended at the end), so an id embedded in a message body/URL no longer wins via leftmost match. - log_filter: strip ANSI SGR escapes before head detection and field extraction so colorized captures filter correctly (production pods are non-TTY, but this closes a latent no-op). - mcp_tools _health: an explicit container_id that misses the exact capture lookup with no agent_role now returns a miss instead of substituting the newest-overall capture (which could hand the operator a different job's logs). A role filter remains a legitimate re-narrowing.
|
Thanks for the thorough review. Both reviews approved; addressing the four non-blocking findings from the 1. 2. MCP fuzzy fallback can return an unrelated agent's logs — 3. Console filtering silently no-ops under ANSI colors — 4. Per-removal snapshot adds synchronous k8s I/O to the reap path —
— Authored by egg |
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
No agent-mode design concerns.
Re-reviewed the delta since my last pass (commit e928f75, addressing the general review bot's non-blocking findings): ANSI-stripping and last-token id matching in log_filter.py, and the _persisted_agent_logs_fallback miss-on-ambiguity fix in _health.py. This is operator-facing observability plumbing — log parsing and log-selection logic — with no prompt assembly, structured-output-for-humans, post-processing of agent output, or model identifiers involved. The _health.py change (return a miss rather than substitute an unrelated job's newest capture when an explicit container_id misses with no role) is in fact aligned with agent-mode principles: it declines to silently hand the operator the wrong job's logs.
— Authored by egg
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
Re-review: PR #3566 — Operator observability (delta since 789ce6b)
I re-reviewed the new commit e928f75 "Harden log-filter id matching and persisted-logs fallback", which addresses three of the four non-blocking findings from my prior review. I traced each fix against its real execution environment (the actual ConsoleFormatter, the handle_tool_call dispatch) and confirmed the tests exercise the production path rather than hand-built fixtures. All three are correctly fixed. No new blocking issues. Approving.
Finding 1 — leftmost id match picks the wrong id (log_filter.py) — ✅ fixed & verified
_extract_pipeline_id now does _CONSOLE_ID_RE.findall(_strip_ansi(head))[-1]. Since ConsoleFormatter appends structured kwargs after the message (format() builds parts as timestamp/level → message → inline key=value → source location), the record's authoritative id is always the last pipeline_id=/task_id= token, and nothing carrying an id token can follow it (the trailing [path:lineno] has none). A body-embedded ?pipeline_id=other-1 can no longer win. test_pipeline_id_prefers_trailing_kwarg_over_message_body asserts both directions (the trailing id keeps the record; the body id returns "").
Finding 3 — silent no-op under ANSI colors (log_filter.py) — ✅ fixed & verified
_strip_ansi is applied before head detection (_group_records), severity extraction, and id extraction. I confirmed the fix is genuinely load-bearing against the real formatter: with use_colors=True, a single inline pair renders as \033[90mpipeline_id=…\033[0m, so the m closing the SGR escape sits immediately before pipeline_id and defeats the (?<![\w.-]) lookbehind — no match without stripping. Original lines are preserved in the record (only the matched-against copy is stripped), so output fidelity is unchanged. test_colorized_console_lines_parity exercises the real ConsoleFormatter(use_colors=True) and sanity-asserts the fixture actually carries \x1b[.
Finding 2 — fuzzy fallback returns an unrelated agent's logs (_health.py) — ✅ fixed & verified
_persisted_agent_logs_fallback now returns None when an explicit container_id misses the exact lookup and no agent_role was supplied, instead of substituting newest-capture-overall. Newest-overall stays correctly reserved for the container_id is None auto-select path (invoked with None at line 124). Both tests drive the real handle_tool_call("get_container_logs", …) dispatch: the no-role test asserts the index endpoint is never consulted (index_calls == []) and the original error surfaces; the with-role test confirms role re-narrowing still serves the role's capture.
Finding 4 — per-removal snapshot k8s I/O — declined (agreed)
I flagged this as "acceptable; for awareness" with no requested change; declining it is correct.
Non-blocking observation (new, minor)
In the post-auto-select fetch-failure path (_health.py:147), the fallback is called with the original agent_role (which is None when the operator passed neither role nor container_id), not selected.get("agent_role"). So when auto-select picks a container, the live fetch loses a race, and the exact-by-uid capture lookup misses, the new guard now re-raises rather than recovering via the already-known role of the selected container. This is the safe direction (fail-loud, never wrong logs), so it is not blocking — but forwarding agent_role or selected.get("agent_role") at line 147 would let role re-narrowing recover the capture in that race window instead of erroring. Worth considering; not required for merge.
Verdict
The three fixes are minimal, correct, and backed by tests that hit the production code path (real formatter / real dispatch, not self-seeded goldens). The rest of the PR is unchanged from the approved 789ce6ba. Approving.
— Authored by egg
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
When get_container_logs auto-selects a container (neither container_id
nor agent_role supplied) and the live log fetch loses the race, the
persisted-logs fallback was called with the original agent_role=None.
The auto-selected container_id is a pod UID, so it misses the
job-name-keyed exact lookup, and the miss-on-ambiguity guard then gave
up rather than recovering via the selected container's known role.
Forward agent_role or selected.get("agent_role") so role re-narrowing
can recover the capture in that race window, while still failing loud
(never substituting an unrelated job's logs) when no role is known.
Addresses #3566 re-review non-blocking finding.
|
Thanks for the re-review — both passes approved. Addressing the one new non-blocking observation from the re-review (commit Non-blocking observation — post-auto-select fetch-failure forwards the original
— Authored by egg |
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
No agent-mode design concerns.
Re-reviewed the delta since my last pass (commit e928f75): a single commit 8f94f3a "Forward auto-selected role to persisted-logs fallback", which directly addresses the one non-blocking observation from my prior re-review. It touches only orchestrator/mcp_tools/_health.py (+1 test).
The change forwards agent_role or selected.get("agent_role") into _persisted_agent_logs_fallback on the post-auto-select live-fetch-failure path, so role re-narrowing can recover the capture when the auto-selected pod-UID container_id misses the job-name-keyed lookup — while the miss-on-ambiguity guard still fails loud (never substituting an unrelated job's logs) when no role is known. selected is initialized to {} at the top of the handler, so the call is safe on the explicit-container_id path too.
This is operator-facing observability plumbing (log-selection logic) — no prompt assembly, structured-output-for-humans, post-processing of agent output, or model identifiers involved. The safe-direction behavior (decline rather than hand back the wrong job's logs) remains aligned with agent-mode principles.
— Authored by egg
This comment has been minimized.
This comment has been minimized.
There was a problem hiding this comment.
Re-review: PR #3566 — delta since e928f75 (commit 8f94f3a)
I re-reviewed the single new commit 8f94f3a "Forward auto-selected role to persisted-logs fallback", which addresses the one non-blocking observation from my prior re-review. Traced the fix against its real execution path (handle_tool_call → _handle_get_container_logs → _persisted_agent_logs_fallback) and confirmed the test exercises production dispatch. Correctly fixed. No new blocking issues. Approving.
The observation is resolved — verified
_handle_get_container_logs now forwards agent_role or selected.get("agent_role") into the fallback on the live-fetch failure path (_health.py:152-154). In the pure auto-select race window (operator passed neither container_id nor agent_role, the live fetch 404s, and the auto-selected pod-UID misses the job-name-keyed exact lookup), the fallback now receives the selected container's known role, so role re-narrowing recovers the capture instead of the miss-on-ambiguity guard giving up. The fix is surgical:
- Explicit-
container_idpath unchanged.selectedstays{}(initialized at_health.py:107, only populated inside theif not container_id:block), soselected.get("agent_role")isNoneand the expression collapses to the prioragent_role. The strict "returnNoneon explicit-container miss with no role" hardening from the earlier finding #2 is fully preserved — I confirmedtest_explicit_container_miss_no_role_does_not_serve_unrelatedstill asserts the index endpoint is never consulted. - Fail-loud preserved. When no role is knowable anywhere (both
agent_roleandselected.get("agent_role")areNone), the resolved role isNone, the miss-on-ambiguity guard at_health.py:197fires, and the original fetch error re-raises. An unrelated job's newest-overall capture is never substituted. - No wrong-role risk. The forwarded role is the selected container's own
agent_role, so role-narrowing returns that role's newest capture — the right role by construction. (If the role had multiple restarts the newest capture may be a different instance thanselected, but that matches the "best-effort recover the relevant logs" semantic auto-select already embodies, and is strictly better than erroring.)
Test quality — production path, regression-protective
test_auto_selected_container_forwards_role_to_fallback drives the real handle_tool_call("get_container_logs", {"task_id": "issue-42"}) (no container_id, no agent_role — the pure auto-select path), mocking only the _make_request HTTP boundary. Not a self-seeding golden, not a hand-built fixture bypassing the helper. I confirmed it is regression-protective: reverting _health.py:153 to bare agent_role makes the fallback receive None, the guard returns a miss, the original HTTPError re-raises, and the result["source"] == "persisted" assertion fails.
I ran the targeted class locally: TestGetContainerLogsPersistedFallback — 6 passed. ruff check and ruff format --check clean on both changed files.
Verdict
Minimal, correct fix to a non-blocking suggestion I raised, backed by a test that hits the production code path. The rest of the PR is unchanged from the previously-approved e928f75. Approving.
— Authored by egg
|
egg review completed. View run logs 9 previous review(s) hidden. |
Summary
Closes #3547 (pain points 1, 2, 3, 4, and 6). Pain point 5 (
get_status.recent_messagesstaleness) is already tracked by #3241 and is not addressed here.Four independent fixes, one per suggestion in the issue:
1. One-shot agent logs survive the reap (pain point 1)
orchestrator/agent_log_store.py: Redis-backed store (same Redis and best-effort contract assession_state_store), keyedagent-logs:{pipeline_id}:{job_name}, 24h TTL, 1 MiB tail cap.KubernetesSpawner.remove_agent_jobnow snapshots the pod's log tail (plus pipeline/role/slice labels and exit code, via the newKubernetesClient.read_job_log_snapshot) into the store immediately before deleting the Job. This covers the [issue-3064][slice-3/6] Failure supervision re-homing: bounded... #3181 observe-once sweep, the Plan phase: concurrent warm-resumed same-role producers race on shared draft → version thrash + stuck-phase alert #3337 superseded-sibling teardown, and pipeline cleanup; capture is strictly best-effort and can never block removal.GET .../containers/<id>/logsfalls back to the capture when the live pod is gone (payload carriessource: persistedplus capture metadata) instead of returning 404.GET .../agent-logs(index, newest first, metadata only) andGET .../agent-logs/<job_name>(full body).get_container_logsMCP tool falls back to the captures when no live container matches the requested role, or when the live fetch 404s.Known gap: a Job reaped solely by
ttlSecondsAfterFinished(600s) without the orchestrator ever callingremove_agent_jobis not captured. In the event-driven model the loop's observe-once sweep is the primary reaper, so this covers the incident path; TTL-only reaps still lose stdout (the transcript read path below is the durable backstop).2. Operator read path for session transcripts (pain point 2)
get_agent_transcriptMCP tool: reads the transcript pushed bysession-state pushon every event-pod exit and returns the last N JSONL lines plussession_id/window_occupancy. On a miss (or withagent_roleomitted) it returns the available(agent_role, slice_id)records so the operator can retry without guessing keys.SessionStateStore.list_records(SCAN-based, metadata only) andGET .../session-state/index.3. Consensus poll spam demoted (pain point 3)
check_consensusruns every ~5s per active slice and logged "Consensus incomplete — checking fallbacks" plus "Skipping pipeline-wide message-bus fallback ..." at INFO on every tick. These (and the pipeline-scoped "Message-bus fallback: not all roles confirmed" sibling) now log at INFO only when the incomplete state (confirmed count, blocking set, unresolved-NACK flag) changes, and at DEBUG otherwise. Reaching consensus resets the memo so the next round's first observation is INFO again. State changes remain fully visible at INFO; the per-tick repeats stop defining the service's noise floor.4.
pipeline_idfilter fixed + tracebacks stay whole (pain points 4 and 6)Root cause of the empty
pipeline_idresults:log_filteronly parsed structured JSON, butJsonFormatteractivates only when the environment detects as GCP (K_SERVICE, which nothing sets). Production pods emitConsoleFormattertext withpipeline_id=...inline, so the filter dropped every line. The existing tests built all fixtures withjson.dumps, which is why this passed CI.filter_log_linesnow groups physical lines into logical records (a record starts at a JSON object line or a consoletimestamp [LEVEL]head; traceback frames and other continuations attach to the preceding record) and evaluates filters per record.pipeline_idmatches the inlinepipeline_id=/task_id=pair on console records (JSON extraction unchanged);levelreads the console[LEVEL]bracket;patternsearches the record's full text, so matching an exception message returns the whole stack instead of one orphaned frame.ConsoleFormatter, including multi-line traceback grouping.Testing
make lintclean.make test(changeset-aware, 21,520 passed). The 4 failures in the run (test_reap_stale_egg_imagessafety guard x2,test_git_clientworktrees-parent detection,test_per_slice_brc_commitgateway allowlist) fail identically on unmodifiedmainin this environment; they are pre-existing and unrelated to this diff.test_agent_log_store.py,test_consensus_log_dedup.py,test_log_filter.py(console + traceback classes),test_containers_routes.py,test_kubernetes_spawner.py,test_mcp_tools.py,test_session_state_store.py,test_session_state_routes.py.