From 5c89e5f5757b45c1d6c167583d8574daebcdcdc4 Mon Sep 17 00:00:00 2001 From: Chris Lee Date: Wed, 9 Sep 2026 19:05:20 +1000 Subject: [PATCH 1/3] feat(orchestrator): capture runner Pod post-mortem before cleanup When a runner Pod dies mid-attempt the failure comment says only that the runner stopped renewing its lease, which cannot separate an OOMKill from a crash from a node eviction. By the time anyone asks, cleanup has deleted the Pod, its terminated container status and its log, and the cluster log pipeline is not a dependable second copy: a dead runner on this deployment showed 547 lines in the Datadog aggregate API and zero retrievable events in search. The reconciler now reads the Pod once, on the first pass that sees it stalled, and persists the kubelet reason, exit code, signal, Pod-level verdict and a secret-stripped 200-line log tail to `workflow_runs.state._runnerPostMortem`. The write is fenced on the key being absent and on `attempt_id`, so the first reading survives the 30s loop and a superseded attempt cannot stamp the current one, and an all-null reading is discarded rather than spending the one-shot slot. Capture runs regardless of what the terminalization branches do, because that pass is the only moment the controller holds both the evidence and a live Pod. The public failure comment gains one line carrying only the kubelet reason and exit code, both shape-checked. The termination message and log tail are repository content and stay in the controller log. `_runnerPostMortem` joins the controller-reserved state keys so a runner cannot pre-set it and suppress its own post-mortem, and the WebSocket close line now carries the run and attempt ids so an abnormal 1006 close ties to the run it ended. Needs `pods/log` `get` on the runner namespace Role. Without it the capture degrades to the terminated container status and records why. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TGnjV4sgzrDCVNznUQ1uuv --- docs/operate/deployment.md | 6 + docs/operate/observability.md | 34 ++- src/k8s/workflow-runner-postmortem.ts | 136 +++++++++++ src/orchestrator/workflow-expiry-notifier.ts | 34 +++ .../workflow-runner-reconciler.ts | 71 ++++++ src/orchestrator/workflow-runner-store.ts | 51 ++++ src/orchestrator/ws-server.ts | 16 +- src/shared/workflow-runner-messages.ts | 10 +- test/k8s/workflow-runner-postmortem.test.ts | 231 ++++++++++++++++++ .../workflow-expiry-notifier.test.ts | 86 +++++++ .../workflow-runner-reconciler.test.ts | 152 +++++++++++- .../workflow-runner-store.test.ts | 67 +++++ 12 files changed, 884 insertions(+), 10 deletions(-) create mode 100644 src/k8s/workflow-runner-postmortem.ts create mode 100644 test/k8s/workflow-runner-postmortem.test.ts diff --git a/docs/operate/deployment.md b/docs/operate/deployment.md index 37cd2dc..31e43c5 100644 --- a/docs/operate/deployment.md +++ b/docs/operate/deployment.md @@ -313,6 +313,12 @@ rules: - apiGroups: [""] resources: ["pods"] verbs: ["create", "get", "delete"] + # Post-mortem only. Without it a dead runner's last output is unrecoverable, + # because cleanup deletes the Pod minutes after it dies. The controller + # degrades to recording the terminated container status alone. + - apiGroups: [""] + resources: ["pods/log"] + verbs: ["get"] - apiGroups: [""] resources: ["secrets"] verbs: ["create", "get", "update", "delete"] diff --git a/docs/operate/observability.md b/docs/operate/observability.md index 9be783f..c92b73c 100644 --- a/docs/operate/observability.md +++ b/docs/operate/observability.md @@ -445,17 +445,39 @@ Structured lifecycle events for `workflow_runs` state transitions, emitted at th `Workflow runner resources reconciled` (`src/k8s/workflow-runner-spawner.ts#ensureWorkflowRunnerResources`) is emitted once per attempt per reconciler pass, carrying `runId`, `attemptId` and `podName`. Two fields report what kubelet is doing with the Pod, which is how the controller separates a Pod that is still coming up from a runner that will never report in. -| Field | Values | Meaning | -| --------------- | -------------------------------------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `startupPhase` | `starting` | Pod is not up yet: unscheduled, pulling, initialising volumes, or read back before it reported any status. The pass extends the startup lease, bounded by the attempt deadline and by `WORKFLOW_RUNNER_STARTUP_BUDGET_MS`. | -| `startupPhase` | `running` | Container started or already finished. Heartbeat renewals own the lease from here. | -| `startupPhase` | `stalled` | The attempt is terminalized on this pass rather than waiting out the lease. | -| `startupReason` | `InvalidImageName`, `ErrImageNeverPull`, `PodFailed`, or `not ready within 900s ()` | Present only when `startupPhase` is `stalled`. Also appears in the failure comment as `Runner Pod could not start: `. | +| Field | Values | Meaning | +| --------------- | -------------------------------------------------------------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `startupPhase` | `starting` | Pod is not up yet: unscheduled, pulling, initialising volumes, or read back before it reported any status. The pass extends the startup lease, bounded by the attempt deadline and by `WORKFLOW_RUNNER_STARTUP_BUDGET_MS`. | +| `startupPhase` | `running` | Container started or already finished. Heartbeat renewals own the lease from here. | +| `startupPhase` | `stalled` | The Pod is dead or permanently blocked. Terminalized on this pass **only before the payload is issued**; after that the attempt is left to lease expiry, and in both cases the pass captures a Pod post-mortem first (see below). | +| `startupReason` | `InvalidImageName`, `ErrImageNeverPull`, `PodFailed`, or `not ready within 900s ()` | Present only when `startupPhase` is `stalled`. Also appears in the failure comment as `Runner Pod could not start: `. | A run of consecutive `startupPhase=starting` lines for one `attemptId` measures total startup delay, not image-pull time alone: scheduling, volume setup and container creation all report the same phase. Before blaming a cold image cache, read the Pod's conditions and events (`kubectl describe pod `), which separate `Unschedulable` from `ImagePullBackOff` from volume attachment. The `startupReason` on the eventual `stalled` line names the blocker the controller last saw. `Workflow runner startup lease extension refused` (`src/orchestrator/workflow-runner-reconciler.ts#reconcileActiveResources`) carries `runId` and `attemptId`. It means a `starting` pass did not actually extend the lease, because the payload was issued in the registration race, the lease lapsed between listing and the update, or the attempt deadline was reached. Without it, an attempt dying mid-startup looks identical to one being kept alive: both keep logging `starting`. +## Workflow runner Pod post-mortem + +`event: "workflow_runner_pod_died"` (`src/orchestrator/workflow-runner-reconciler.ts#capturePodPostMortem`) is logged at `error` the first time a reconciler pass sees a `stalled` Pod for an attempt, and at most once per attempt. It is the answer to "why did the lease expire", which the lease-expiry notice itself cannot give. + +It exists because everything else is gone by the time anyone asks. Cleanup deletes the Pod, and with it the terminated container status and the container log, within seconds of the run being terminalized. A cluster log pipeline is not a dependable second copy: on this deployment the Datadog Logs **aggregate** API counted 547 lines for a dead runner while the **search** API returned zero retrievable events, and no container metrics were collected at all. + +| Field | Meaning | +| ----------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `podName`, `podPhase` | Which Pod, and its phase at capture (`Failed` for a container that exited non-zero under `restartPolicy: Never`). | +| `reason` | Kubelet's **container** termination reason. `OOMKilled` is the memory limit; `Error` is a non-zero exit. | +| `podReason`, `podMessage` | The **Pod**-level verdict, which is where a node decision lands: `Evicted` for node pressure such as a filled ephemeral-storage limit, `DeadlineExceeded` for `activeDeadlineSeconds`. A container that never ran leaves `reason` null and only these set. | +| `runId`, `attemptId`, `workflowName`, `startupReason` | Attempt identity plus the blocker the reconciler last saw, so the line joins to the `startupPhase` trail above. | +| `exitCode`, `signal` | `137` with `OOMKilled` is the kernel OOM killer. A bare `137` without that reason is an external `SIGKILL`. | +| `message` | The container's termination message, when the runtime set one. | +| `startedAt`, `finishedAt` | Container lifetime. `finishedAt` should match the abnormal WebSocket close, see below. | +| `logTail` | Last 200 lines of runner stdout, secret-stripped and capped at 16 KB. Empty when `pods/log` RBAC is missing. | +| `logError` | Why `logTail` is empty. A `403` here means the Role is missing `pods/log` `get`, see the deployment RBAC. | + +The same record is persisted to `workflow_runs.state._runnerPostMortem`, so it survives log rotation and is queryable per run. The failure comment quotes only the kubelet reason (`reason`, falling back to `podReason`) and `exitCode`, and shape-checks it against `^[A-Za-z][A-Za-z0-9]{0,63}$` first; `message`, `podMessage` and `logTail` are repository or node content and stay in the controller log. An all-null reading is discarded rather than recorded, so a pass that catches the Pod before kubelet wrote its status does not spend the one-shot slot. + +Correlate with the socket: `WebSocket connection closed` carries `kind`, plus `runId` and `attemptId` for a `workflow-runner` socket. Close code `1006` (abnormal, no close frame) at the same second as `finishedAt` is the signature of a runner killed outright rather than one shutting down. + ## Workspace lifecycle events The `workspace.*` family makes the non-success workspace-cleanup paths greppable, complementing the success-path `pipeline.stage stage=workspace.cleanup` row and the startup `workspace.sweep` reaper. Schema pinned by `WorkspaceLogFieldsSchema` (`src/core/workspace-events.ts#WorkspaceLogFieldsSchema`). `workDir` is a process-local temp path and safe to log; the authenticated clone URL embeds the install token and is never logged (clone events carry the `owner/repo` slug and branch only). All `err` fields routed through `redactErrorMessage`. diff --git a/src/k8s/workflow-runner-postmortem.ts b/src/k8s/workflow-runner-postmortem.ts new file mode 100644 index 0000000..05ef1b1 --- /dev/null +++ b/src/k8s/workflow-runner-postmortem.ts @@ -0,0 +1,136 @@ +import type { V1ContainerStateTerminated, V1Pod } from "@kubernetes/client-node"; + +import { config } from "../config"; +import { redactSecrets } from "../utils/sanitize"; +import { loadKubernetesClient } from "./ephemeral-daemon-spawner"; +import { workflowRunnerResourceNames } from "./workflow-runner-spawner"; + +const RUNNER_CONTAINER = "runner"; + +// The Pod and its logs are deleted on cleanup, seconds after the run is +// terminalized, and nothing outside the cluster is a dependable second copy: +// a log pipeline can retain counts while returning no searchable events. Keep +// enough tail to hold a stack trace, capped so one runaway line cannot bloat +// the `workflow_runs` row or the controller's own log. +const LOG_TAIL_LINES = 200; +const LOG_TAIL_BYTES = 16_384; +// A ceiling on the transfer, not the tail. `limitBytes` stops the server after N +// bytes of a stream that arrives oldest-first, so setting it to LOG_TAIL_BYTES +// would discard the newest lines, which is exactly the crash. Kept well above +// the tail so the local slice is what decides, while one pathological line still +// cannot pull an unbounded body into the controller. +const LOG_READ_CEILING_BYTES = 262_144; +// A Kubernetes error body can be a full HTML page; only the head identifies it. +const LOG_ERROR_CHARS = 200; + +/** Why the runner container died, plus the runner's own last output. */ +export interface RunnerPodPostMortem { + readonly podName: string; + readonly podPhase: string; + /** + * Pod-level verdict, set by the node rather than the container runtime. + * Node-pressure eviction lands here as `Evicted`, never in the container's + * terminated state, so without these an ephemeral-storage kill records an + * all-null post-mortem and the failure comment says nothing. + */ + readonly podReason: string | null; + readonly podMessage: string | null; + readonly exitCode: number | null; + readonly reason: string | null; + readonly signal: number | null; + readonly message: string | null; + readonly startedAt: string | null; + readonly finishedAt: string | null; + readonly logTail: string; + /** Why `logTail` is empty, when it is. Null when the read succeeded. */ + readonly logError: string | null; +} + +function terminatedState(pod: V1Pod): V1ContainerStateTerminated | undefined { + const status = pod.status?.containerStatuses?.find((c) => c.name === RUNNER_CONTAINER); + // `lastState` holds the exit of a container kubelet already replaced. The + // runner spec uses restartPolicy Never so it is normally empty, but reading + // it costs nothing and covers a restart the spec did not intend. + return status?.state?.terminated ?? status?.lastState?.terminated; +} + +/** The client deserializes these to `Date`; raw API JSON yields strings. */ +function isoOrNull(value: unknown): string | null { + if (value instanceof Date) return value.toISOString(); + return typeof value === "string" ? value : null; +} + +async function readLogTail( + podName: string, + namespace: string, +): Promise<{ readonly tail: string; readonly error: string | null }> { + try { + const raw = await loadKubernetesClient().core.readNamespacedPodLog({ + name: podName, + namespace, + container: RUNNER_CONTAINER, + tailLines: LOG_TAIL_LINES, + limitBytes: LOG_READ_CEILING_BYTES, + }); + // Runner stdout echoes repository content and may carry a token the agent + // printed, so it is stripped before it reaches the controller log or the + // run row. Same rule as every other output path (security invariant #2). + // Sliced from the end: the last lines before the kill are the diagnostic + // ones. redactSecrets only deletes bytes, so this caps the redacted text. + return { tail: redactSecrets(raw).body.slice(-LOG_TAIL_BYTES), error: null }; + } catch (err) { + const message = err instanceof Error ? err.message : String(err); + return { tail: "", error: message.slice(0, LOG_ERROR_CHARS) }; + } +} + +/** Node-level verdict. An eviction appears only here, never on the container. */ +function podFields(pod: V1Pod): Pick { + return { + podPhase: pod.status?.phase ?? "unknown", + podReason: pod.status?.reason ?? null, + podMessage: pod.status?.message ?? null, + }; +} + +/** Container-level verdict. All null when the container never ran. */ +function containerFields( + pod: V1Pod, +): Omit< + RunnerPodPostMortem, + "podName" | "podPhase" | "podReason" | "podMessage" | "logTail" | "logError" +> { + const state = terminatedState(pod); + return { + exitCode: state?.exitCode ?? null, + reason: state?.reason ?? null, + signal: state?.signal ?? null, + message: state?.message ?? null, + startedAt: isoOrNull(state?.startedAt), + finishedAt: isoOrNull(state?.finishedAt), + }; +} + +/** + * Read the runner Pod's cause of death while the Pod still exists. + * + * Lease expiry is a symptom: it says the runner stopped renewing, never why. + * The answer lives in the container's terminated state (an OOMKill and a crash + * are both "stopped renewing") and in its final log lines, and both are + * destroyed with the Pod. Returns null when the Pod is already gone, since the + * caller's failure path does not depend on this. + */ +export async function readWorkflowRunnerPostMortem(attempt: { + readonly attemptId: string; +}): Promise { + const namespace = config.workflowRunnerNamespace; + const { podName } = workflowRunnerResourceNames(attempt.attemptId); + let pod: V1Pod; + try { + pod = await loadKubernetesClient().core.readNamespacedPod({ name: podName, namespace }); + } catch { + return null; + } + const { tail, error } = await readLogTail(podName, namespace); + return { podName, ...podFields(pod), ...containerFields(pod), logTail: tail, logError: error }; +} diff --git a/src/orchestrator/workflow-expiry-notifier.ts b/src/orchestrator/workflow-expiry-notifier.ts index bcc5e96..51537e9 100644 --- a/src/orchestrator/workflow-expiry-notifier.ts +++ b/src/orchestrator/workflow-expiry-notifier.ts @@ -218,6 +218,38 @@ export async function notifyWorkflowAttemptFailures( } } +// Shape of a kubelet reason: a short CamelCase identifier such as OOMKilled, +// Error or Evicted. Checked rather than trusted, so a value that ever reached +// this state key from somewhere other than the reconciler still cannot carry +// markdown or an arbitrary-length body onto a public comment. +const KUBELET_REASON = /^[A-Za-z][A-Za-z0-9]{0,63}$/; + +/** + * One line naming the runner Pod's cause of death, when the reconciler caught + * it. Without it the reader gets "the runner stopped renewing" and no way to + * tell an OOMKill from a crash without cluster access the Pod no longer has. + * + * Deliberately only the kubelet reason and `exitCode`, both bounded enum-ish + * values. The terminated `message` and the log tail are repository content and + * stay in the controller log rather than on a public comment. + */ +function podPostMortemLine(row: WorkflowRunRow): string | null { + const raw = row.state["_runnerPostMortem"]; + if (raw === null || typeof raw !== "object") return null; + const postMortem = raw as Record; + // Container reason first: it is the specific verdict. `podReason` is the + // node-level one, the only place an ephemeral-storage eviction appears. + const reason = postMortem["reason"] ?? postMortem["podReason"]; + const exitCode = postMortem["exitCode"]; + const parts: string[] = []; + if (typeof reason === "string" && KUBELET_REASON.test(reason)) parts.push(reason); + if (typeof exitCode === "number" && Number.isInteger(exitCode)) { + parts.push(`exit code ${exitCode}`); + } + if (parts.length === 0) return null; + return `The runner Pod terminated: ${parts.join(", ")}. Container status and log tail are in the controller logs under \`event: "workflow_runner_pod_died"\`.`; +} + export async function notifyExpiredWorkflowAttempts( rows: readonly WorkflowRunRow[], ): Promise { @@ -234,6 +266,7 @@ export async function notifyExpiredWorkflowAttempts( // telling the reader to go inspect the repository is false and sends them // hunting for damage that cannot exist. const ranNothing = row.runner_payload_issued_at === null; + const postMortem = podPostMortemLine(row); return [ deadlineExpired ? "❌ **Workflow execution deadline expired**" @@ -243,6 +276,7 @@ export async function notifyExpiredWorkflowAttempts( ? "The immutable attempt deadline elapsed before completion was confirmed. The database marked the workflow failed and released its in-flight lock." : "The runner stopped renewing this attempt before completion was confirmed. The database marked the workflow failed and released its in-flight lock.", "", + ...(postMortem === null ? [] : [postMortem, ""]), ranNothing ? "The runner never started, so no repository or GitHub changes were made. Re-triggering the workflow is safe." : `External GitHub or git operations may have completed before the ${deadlineExpired ? "deadline" : "lease"} expired. Inspect the repository before re-triggering the workflow.`, diff --git a/src/orchestrator/workflow-runner-reconciler.ts b/src/orchestrator/workflow-runner-reconciler.ts index 3edef35..abb2109 100644 --- a/src/orchestrator/workflow-runner-reconciler.ts +++ b/src/orchestrator/workflow-runner-reconciler.ts @@ -1,3 +1,7 @@ +import { + readWorkflowRunnerPostMortem, + type RunnerPodPostMortem, +} from "../k8s/workflow-runner-postmortem"; import { WorkflowRunnerResourceError } from "../k8s/workflow-runner-spawner"; import { logger } from "../logger"; import { reconcilePendingWorkflowFailureNotifications } from "./workflow-expiry-notifier"; @@ -15,9 +19,66 @@ import { import { extendWorkflowRunnerStartupLease, findWorkflowRunnerCleanupCandidates, + hasWorkflowRunnerPostMortem, listActiveWorkflowRunnerAttempts, + recordWorkflowRunnerPostMortem, + type WorkflowRunnerAttempt, } from "./workflow-runner-store"; +/** + * Persist and log why the runner Pod died, at most once per attempt. + * + * This is the only durable record. The Pod, its terminated container status and + * its logs are deleted on cleanup, so by the time anyone reads the failure + * comment there is nothing left to inspect, and "the runner stopped renewing" + * cannot distinguish an OOMKill from a crash from a node eviction. + * + * Never throws: a post-mortem that cannot be read must not derail the failure + * path that prompted it. + */ +/** + * Whether the reading says anything the failure comment or an operator could + * use. A pass that catches the Pod before kubelet has written any status reads + * all nulls, and the store keeps the first write forever, so recording that + * would spend the one slot on nothing and lock out the pass that has the answer. + */ +function isInformative(postMortem: RunnerPodPostMortem): boolean { + return ( + postMortem.reason !== null || + postMortem.podReason !== null || + postMortem.exitCode !== null || + postMortem.logTail !== "" + ); +} + +async function capturePodPostMortem( + attempt: WorkflowRunnerAttempt, + startupReason: string, +): Promise { + try { + if (await hasWorkflowRunnerPostMortem(attempt)) return; + const postMortem = await readWorkflowRunnerPostMortem(attempt); + if (postMortem === null || !isInformative(postMortem)) return; + if (!(await recordWorkflowRunnerPostMortem(attempt, { ...postMortem }))) return; + logger.error( + { + event: "workflow_runner_pod_died", + runId: attempt.runId, + attemptId: attempt.attemptId, + workflowName: attempt.workflowName, + startupReason, + ...postMortem, + }, + "Workflow runner Pod died", + ); + } catch (err) { + logger.warn( + { err, runId: attempt.runId, attemptId: attempt.attemptId }, + "Workflow runner post-mortem capture failed", + ); + } +} + async function reconcileActiveResources(): Promise { // Reuse the dispatch validator so both paths apply one rule. A hand-rolled // `undefined`-only guard here would let an empty-string `DAEMON_IMAGE` through @@ -50,6 +111,16 @@ async function reconcileActiveResources(): Promise { }); if (result.state !== "ready") continue; + // Observing a dead Pod is not the same as acting on it, so this runs + // regardless of what the branches below do with the attempt. It is the + // only moment the controller holds both the evidence and a live Pod: the + // lease has minutes left and neither the terminalization below nor its + // cleanup has deleted anything yet. + if (result.startup.phase === "stalled") { + // eslint-disable-next-line no-await-in-loop -- one post-mortem per attempt, in order + await capturePodPostMortem(attempt, result.startup.reason); + } + // Startup handling only. Once the payload is issued the runner holds its // credential and may have pushed commits, so a dead Pod is not a start // failure: leave it to lease expiry, whose notice tells the reader to diff --git a/src/orchestrator/workflow-runner-store.ts b/src/orchestrator/workflow-runner-store.ts index eb61ead..83648f5 100644 --- a/src/orchestrator/workflow-runner-store.ts +++ b/src/orchestrator/workflow-runner-store.ts @@ -771,6 +771,57 @@ export async function extendWorkflowRunnerStartupLease( return rows[0] !== undefined; } +/** + * Record why the runner Pod died, once per attempt. + * + * Fenced on the key being absent, so the 30s reconcile loop stores the first + * reading instead of overwriting it with a progressively emptier one as + * Kubernetes garbage-collects the Pod, and on `attempt_id`, so a superseded + * attempt cannot stamp the current one. True only for the write that landed, + * which is also the caller's cue to emit the log line exactly once. + * + * `jsonb_exists` rather than the `?` operator: `?` is a placeholder marker in + * enough SQL layers that the function form is the safer spelling here. + */ +/** + * Whether this attempt already has a post-mortem on record. + * + * Consulted before the two Kubernetes reads, which is the only reason it exists: + * a stalled attempt whose payload was issued is left to lease expiry, so it stays + * stalled for every pass until the lease runs out, and without this each of those + * passes re-reads the Pod and up to 16 KB of its log only for the fenced write + * below to discard the result. + */ +export async function hasWorkflowRunnerPostMortem( + attempt: { readonly runId: string; readonly attemptId: string }, + sql: SQL = requireDb(), +): Promise { + const rows: { present: boolean }[] = await sql` + SELECT jsonb_exists(state, '_runnerPostMortem') AS present + FROM workflow_runs + WHERE id = ${attempt.runId} + AND attempt_id = ${attempt.attemptId} + `; + return rows[0]?.present === true; +} + +export async function recordWorkflowRunnerPostMortem( + attempt: { readonly runId: string; readonly attemptId: string }, + postMortem: Record, + sql: SQL = requireDb(), +): Promise { + const patch = { _runnerPostMortem: postMortem }; + const rows: { id: string }[] = await sql` + UPDATE workflow_runs + SET state = state || ${patch}::jsonb + WHERE id = ${attempt.runId} + AND attempt_id = ${attempt.attemptId} + AND NOT jsonb_exists(state, '_runnerPostMortem') + RETURNING id + `; + return rows[0] !== undefined; +} + /** Fail one claimed runner attempt and its execution receipt atomically. */ export async function failWorkflowRunnerAttempt( attempt: WorkflowRunnerAttempt, diff --git a/src/orchestrator/ws-server.ts b/src/orchestrator/ws-server.ts index 52882b3..e3badee 100644 --- a/src/orchestrator/ws-server.ts +++ b/src/orchestrator/ws-server.ts @@ -294,7 +294,21 @@ export function startWebSocketServer(): ReturnType, code: number, reason: string) { - logger.info({ daemonId: ws.data.daemonId, code, reason }, "WebSocket connection closed"); + logger.info( + { + daemonId: ws.data.daemonId, + kind: ws.data.kind, + // A workflow-runner socket carries no daemonId, so without these an + // abnormal close (1006, the shape a killed runner produces) cannot + // be tied to the run it ended. + ...(ws.data.kind === "workflow-runner" + ? { runId: ws.data.runnerRunId, attemptId: ws.data.runnerAttemptId } + : {}), + code, + reason, + }, + "WebSocket connection closed", + ); if (ws.data.kind === "workflow-runner") handleWorkflowRunnerClose(ws); else handleWsClose(ws, code, reason); }, diff --git a/src/shared/workflow-runner-messages.ts b/src/shared/workflow-runner-messages.ts index db580d6..39b0691 100644 --- a/src/shared/workflow-runner-messages.ts +++ b/src/shared/workflow-runner-messages.ts @@ -21,7 +21,15 @@ const attemptIdentity = { attemptId: z.uuid(), }; -const CONTROLLER_RESERVED_STATE_KEYS = ["_configNotice", "_lastHumanMessage"] as const; +const CONTROLLER_RESERVED_STATE_KEYS = [ + "_configNotice", + "_lastHumanMessage", + // Written only by the reconciler's post-mortem capture. A runner that could + // pre-set it would suppress its own post-mortem, because the capture is fenced + // on the key being absent, and would choose the text of the public failure + // comment. + "_runnerPostMortem", +] as const; function containsControllerReservedState(value: unknown): boolean { return ( diff --git a/test/k8s/workflow-runner-postmortem.test.ts b/test/k8s/workflow-runner-postmortem.test.ts new file mode 100644 index 0000000..6f5a60b --- /dev/null +++ b/test/k8s/workflow-runner-postmortem.test.ts @@ -0,0 +1,231 @@ +import { beforeEach, describe, expect, it, mock } from "bun:test"; + +const readNamespacedPod = mock( + (_input: { name: string; namespace: string }): Promise => Promise.resolve({}), +); +const readNamespacedPodLog = mock( + (_input: { + name: string; + namespace: string; + container?: string; + tailLines?: number; + limitBytes?: number; + }): Promise => Promise.resolve(""), +); +const core = { readNamespacedPod, readNamespacedPodLog }; + +void mock.module("../../src/config", () => ({ + config: { workflowRunnerNamespace: "runner-ns" }, +})); + +void mock.module("../../src/k8s/ephemeral-daemon-spawner", () => ({ + loadKubernetesClient: (): { core: typeof core } => ({ core }), +})); + +void mock.module("../../src/logger", () => ({ + logger: { + info: mock(() => {}), + warn: mock(() => {}), + error: mock(() => {}), + debug: mock(() => {}), + }, +})); + +const { readWorkflowRunnerPostMortem } = await import("../../src/k8s/workflow-runner-postmortem"); +const { workflowRunnerResourceNames } = await import("../../src/k8s/workflow-runner-spawner"); + +const attemptId = "22222222-2222-4222-8222-222222222222"; +const { podName } = workflowRunnerResourceNames(attemptId); + +function oomKilledPod(): unknown { + return { + status: { + phase: "Failed", + containerStatuses: [ + { + name: "runner", + state: { + terminated: { + exitCode: 137, + reason: "OOMKilled", + signal: 9, + message: null, + startedAt: new Date("2026-09-06T11:41:28Z"), + finishedAt: new Date("2026-09-06T11:54:38Z"), + }, + }, + }, + ], + }, + }; +} + +describe("readWorkflowRunnerPostMortem", () => { + beforeEach(() => { + readNamespacedPod.mockReset(); + readNamespacedPodLog.mockReset(); + readNamespacedPodLog.mockImplementation(() => Promise.resolve("")); + }); + + it("reports the terminated container state that lease expiry cannot", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => Promise.resolve("cloning repo\ncrash\n")); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem).toEqual({ + podName, + podPhase: "Failed", + podReason: null, + podMessage: null, + exitCode: 137, + reason: "OOMKilled", + signal: 9, + message: null, + startedAt: "2026-09-06T11:41:28.000Z", + finishedAt: "2026-09-06T11:54:38.000Z", + logTail: "cloning repo\ncrash\n", + logError: null, + }); + expect(readNamespacedPodLog.mock.calls[0]?.[0]).toMatchObject({ + name: podName, + namespace: "runner-ns", + container: "runner", + tailLines: 200, + // Must stay well above the 16 KB tail. `limitBytes` stops the server after + // N bytes of an oldest-first stream, so a ceiling equal to the tail would + // drop the newest lines, which are the crash. + limitBytes: 262_144, + }); + }); + + it("keeps the newest lines when the log exceeds the tail cap", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => + Promise.resolve(`${"o".repeat(20_000)}\nFATAL: out of memory\n`), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.logTail).toEndWith("FATAL: out of memory\n"); + expect(postMortem?.logTail.length).toBe(16_384); + }); + + // Node-pressure eviction is a Pod-level verdict; the container carries no + // terminated state at all, so reading only containerStatuses would record an + // all-null post-mortem and the failure comment would say nothing. + it("reports a node-pressure eviction from the Pod-level status", async () => { + readNamespacedPod.mockImplementation(() => + Promise.resolve({ + status: { + phase: "Failed", + reason: "Evicted", + message: "The node was low on resource: ephemeral-storage.", + containerStatuses: [], + }, + }), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.podReason).toBe("Evicted"); + expect(postMortem?.podMessage).toContain("ephemeral-storage"); + expect(postMortem?.reason).toBeNull(); + }); + + // Every `stalled` startup reason except PodFailed describes a container that + // never ran, which is the shape the reconciler meets most often. + it("returns an empty container record when the container never started", async () => { + readNamespacedPod.mockImplementation(() => + Promise.resolve({ status: { phase: "Pending", containerStatuses: [] } }), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem).toMatchObject({ podPhase: "Pending", reason: null, exitCode: null }); + }); + + // The client deserializes timestamps to Date; raw API JSON yields strings. + it("passes through timestamps that arrive as strings", async () => { + readNamespacedPod.mockImplementation(() => + Promise.resolve({ + status: { + phase: "Failed", + containerStatuses: [ + { + name: "runner", + state: { + terminated: { + exitCode: 137, + reason: "OOMKilled", + startedAt: "2026-09-06T11:41:28Z", + finishedAt: "2026-09-06T11:54:38Z", + }, + }, + }, + ], + }, + }), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.startedAt).toBe("2026-09-06T11:41:28Z"); + expect(postMortem?.finishedAt).toBe("2026-09-06T11:54:38Z"); + }); + + it("strips secrets out of the captured log tail", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => + Promise.resolve(`token=ghs_${"a".repeat(36)} done`), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.logTail).toBe("token= done"); + }); + + // A missing pods/log RBAC verb must degrade to status-only, not lose the + // whole post-mortem: the exit code alone still separates OOM from crash. + it("keeps the container status when the log read is refused", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => + Promise.reject(new Error("HTTP-Code: 403 forbidden: pods/log")), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.reason).toBe("OOMKilled"); + expect(postMortem?.logTail).toBe(""); + expect(postMortem?.logError).toContain("403"); + }); + + it("falls back to lastState for a container kubelet already replaced", async () => { + readNamespacedPod.mockImplementation(() => + Promise.resolve({ + status: { + phase: "Failed", + containerStatuses: [ + { + name: "runner", + state: {}, + lastState: { terminated: { exitCode: 1, reason: "Error" } }, + }, + ], + }, + }), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.exitCode).toBe(1); + expect(postMortem?.reason).toBe("Error"); + }); + + it("returns null once the Pod is gone", async () => { + readNamespacedPod.mockImplementation(() => Promise.reject(new Error("not found"))); + + expect(await readWorkflowRunnerPostMortem({ attemptId })).toBeNull(); + expect(readNamespacedPodLog).not.toHaveBeenCalled(); + }); +}); diff --git a/test/orchestrator/workflow-expiry-notifier.test.ts b/test/orchestrator/workflow-expiry-notifier.test.ts index 1d53d36..e004bb7 100644 --- a/test/orchestrator/workflow-expiry-notifier.test.ts +++ b/test/orchestrator/workflow-expiry-notifier.test.ts @@ -131,6 +131,92 @@ describe("workflow expiry notifier", () => { expect(call[1].humanMessage).not.toContain("Inspect the repository"); }); + it("names the Pod's cause of death in the lease-expiry notice", async () => { + // "The runner stopped renewing" is a symptom shared by an OOMKill, a crash + // and a node eviction. Without the captured reason the reader has nothing + // to act on: the Pod is deleted before they read the comment. + testConfig.githubPersonalAccessToken = undefined; + const expired = row("solo", null, "workflow execution lease expired"); + expired["runner_payload_issued_at"] = new Date(); + expired["state"] = { + failedReason: "workflow execution lease expired", + _runnerPostMortem: { + reason: "OOMKilled", + exitCode: 137, + message: "secret-bearing container message", + logTail: "secret-bearing log tail", + }, + }; + findById.mockImplementation((id: string) => Promise.resolve(id === "solo" ? expired : null)); + + await notifyExpiredWorkflowAttempts([expired] as never); + + const call = setState.mock.calls[0] as unknown as [unknown, { humanMessage: string }]; + expect(call[1].humanMessage).toContain("The runner Pod terminated: OOMKilled, exit code 137."); + // Repository content stays in the controller log, never on a public comment. + expect(call[1].humanMessage).not.toContain("secret-bearing"); + }); + + // Node-pressure eviction is a Pod-level verdict, so the container reason is + // null. Without the fallback the comment would say nothing at all, which is + // the case an ephemeral-storage limit actually produces. + it("names a node-pressure eviction from the Pod-level reason", async () => { + testConfig.githubPersonalAccessToken = undefined; + const expired = row("solo", null, "workflow execution lease expired"); + expired["runner_payload_issued_at"] = new Date(); + expired["state"] = { + failedReason: "workflow execution lease expired", + _runnerPostMortem: { + reason: null, + podReason: "Evicted", + podMessage: "The node was low on resource: ephemeral-storage.", + exitCode: null, + }, + }; + findById.mockImplementation((id: string) => Promise.resolve(id === "solo" ? expired : null)); + + await notifyExpiredWorkflowAttempts([expired] as never); + + const call = setState.mock.calls[0] as unknown as [unknown, { humanMessage: string }]; + expect(call[1].humanMessage).toContain("The runner Pod terminated: Evicted."); + expect(call[1].humanMessage).not.toContain("ephemeral-storage"); + }); + + // The key is reserved on the runner protocol, so this is the second lock: a + // reason that ever reached the row from elsewhere still cannot carry markdown + // or an arbitrary-length body onto a public comment. + it("drops a reason that is not shaped like a kubelet reason", async () => { + testConfig.githubPersonalAccessToken = undefined; + const expired = row("solo", null, "workflow execution lease expired"); + expired["runner_payload_issued_at"] = new Date(); + expired["state"] = { + failedReason: "workflow execution lease expired", + _runnerPostMortem: { + reason: "OOMKilled](https://evil.example) **do this instead**", + exitCode: 137, + }, + }; + findById.mockImplementation((id: string) => Promise.resolve(id === "solo" ? expired : null)); + + await notifyExpiredWorkflowAttempts([expired] as never); + + const call = setState.mock.calls[0] as unknown as [unknown, { humanMessage: string }]; + expect(call[1].humanMessage).toContain("The runner Pod terminated: exit code 137."); + expect(call[1].humanMessage).not.toContain("evil.example"); + }); + + it("omits the cause-of-death line when no post-mortem was captured", async () => { + testConfig.githubPersonalAccessToken = undefined; + const expired = row("solo", null, "workflow execution lease expired"); + expired["runner_payload_issued_at"] = new Date(); + findById.mockImplementation((id: string) => Promise.resolve(id === "solo" ? expired : null)); + + await notifyExpiredWorkflowAttempts([expired] as never); + + const call = setState.mock.calls[0] as unknown as [unknown, { humanMessage: string }]; + expect(call[1].humanMessage).not.toContain("The runner Pod terminated"); + }); + it("keeps the inspect-the-repository warning once the runner held a token", async () => { testConfig.githubPersonalAccessToken = undefined; const expired = row("solo", null, "workflow execution lease expired"); diff --git a/test/orchestrator/workflow-runner-reconciler.test.ts b/test/orchestrator/workflow-runner-reconciler.test.ts index 028a731..7b2cc78 100644 --- a/test/orchestrator/workflow-runner-reconciler.test.ts +++ b/test/orchestrator/workflow-runner-reconciler.test.ts @@ -49,6 +49,29 @@ const cleanupWorkflowRunnerAttempt = mock((input: { attemptId: string }) => { events.push(`cleanup:${input.attemptId}`); return Promise.resolve(); }); +const defaultPostMortemRead = (input: { attemptId: string }): Promise => { + events.push(`postmortem:read:${input.attemptId}`); + return Promise.resolve({ + podName: `workflow-runner-${input.attemptId}`, + podPhase: "Failed", + podReason: null, + podMessage: null, + exitCode: 137, + reason: "OOMKilled", + signal: 9, + message: null, + startedAt: null, + finishedAt: null, + logTail: "", + logError: null, + }); +}; +const readWorkflowRunnerPostMortem = mock(defaultPostMortemRead); +const hasWorkflowRunnerPostMortem = mock((_input: { attemptId: string }) => Promise.resolve(false)); +const recordWorkflowRunnerPostMortem = mock((input: { attemptId: string }) => { + events.push(`postmortem:record:${input.attemptId}`); + return Promise.resolve(true); +}); const listActiveWorkflowRunnerAttempts = mock(() => Promise.resolve([firstAttempt, secondAttempt])); const findWorkflowRunnerCleanupCandidates = mock(() => Promise.resolve([ @@ -66,11 +89,12 @@ class TestWorkflowRunnerResourceError extends Error { void mock.module("../../src/k8s/workflow-runner-spawner", () => ({ WorkflowRunnerResourceError: TestWorkflowRunnerResourceError, })); +const loggerError = mock((_fields: Record, _msg: string) => undefined); void mock.module("../../src/logger", () => ({ logger: { info: mock(() => undefined), warn: mock(() => undefined), - error: mock(() => undefined), + error: loggerError, debug: mock(() => undefined), }, })); @@ -118,6 +142,11 @@ void mock.module("../../src/orchestrator/workflow-runner-store", () => ({ extendWorkflowRunnerStartupLease, findWorkflowRunnerCleanupCandidates, listActiveWorkflowRunnerAttempts, + recordWorkflowRunnerPostMortem, + hasWorkflowRunnerPostMortem, +})); +void mock.module("../../src/k8s/workflow-runner-postmortem", () => ({ + readWorkflowRunnerPostMortem, })); const { reconcileWorkflowRunners } = @@ -142,7 +171,8 @@ describe("workflow runner reconciliation", () => { }); }); extendWorkflowRunnerStartupLease.mockClear(); - failWorkflowRunnerResourceAttempt.mockClear(); + failWorkflowRunnerResourceAttempt.mockReset(); + failWorkflowRunnerResourceAttempt.mockImplementation(() => Promise.resolve()); cleanupWorkflowRunnerAttempt.mockReset(); cleanupWorkflowRunnerAttempt.mockImplementation((input) => { events.push(`cleanup:${input.attemptId}`); @@ -150,6 +180,12 @@ describe("workflow runner reconciliation", () => { }); listActiveWorkflowRunnerAttempts.mockClear(); findWorkflowRunnerCleanupCandidates.mockClear(); + readWorkflowRunnerPostMortem.mockReset(); + readWorkflowRunnerPostMortem.mockImplementation(defaultPostMortemRead); + hasWorkflowRunnerPostMortem.mockReset(); + hasWorkflowRunnerPostMortem.mockImplementation(() => Promise.resolve(false)); + loggerError.mockClear(); + recordWorkflowRunnerPostMortem.mockClear(); }); it("replays results before repairing active resources and terminal cleanup", async () => { @@ -256,6 +292,118 @@ describe("workflow runner reconciliation", () => { expect(failWorkflowRunnerResourceAttempt).not.toHaveBeenCalled(); expect(extendWorkflowRunnerStartupLease).not.toHaveBeenCalled(); + // But it must still be explained. This pass is the last moment the Pod and + // its logs exist, and lease expiry alone cannot say why the runner died. + expect(readWorkflowRunnerPostMortem).toHaveBeenCalledWith(firstAttempt); + expect(recordWorkflowRunnerPostMortem).toHaveBeenCalledWith( + firstAttempt, + expect.objectContaining({ reason: "OOMKilled", exitCode: 137 }), + ); + // The line an operator greps for. Without it the only trace of an OOMKill is + // a lease-expiry notice that names a symptom. + expect(loggerError).toHaveBeenCalledWith( + expect.objectContaining({ + event: "workflow_runner_pod_died", + runId: firstAttempt.runId, + attemptId: firstAttempt.attemptId, + startupReason: "PodFailed", + reason: "OOMKilled", + exitCode: 137, + }), + "Workflow runner Pod died", + ); + }); + + it("does not re-read the Pod once a post-mortem is on record", async () => { + hasWorkflowRunnerPostMortem.mockImplementation(() => Promise.resolve(true)); + ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "stalled", reason: "PodFailed" }, + payloadIssuedAt: new Date("2026-01-01T00:00:00Z"), + }); + }); + + await reconcileWorkflowRunners(); + + expect(readWorkflowRunnerPostMortem).not.toHaveBeenCalled(); + expect(loggerError).not.toHaveBeenCalled(); + }); + + // A pass that catches the Pod before kubelet wrote any status reads all nulls. + // Recording that would spend the one-shot slot and lock out the pass that has + // the answer, so the empty reading is dropped and the next pass retries. + it("leaves the record open when the reading says nothing", async () => { + readWorkflowRunnerPostMortem.mockImplementation((input: { attemptId: string }) => + Promise.resolve({ + podName: `workflow-runner-${input.attemptId}`, + podPhase: "Running", + podReason: null, + podMessage: null, + exitCode: null, + reason: null, + signal: null, + message: null, + startedAt: null, + finishedAt: null, + logTail: "", + logError: null, + }), + ); + ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "stalled", reason: "PodFailed" }, + payloadIssuedAt: new Date("2026-01-01T00:00:00Z"), + }); + }); + + await reconcileWorkflowRunners(); + + expect(recordWorkflowRunnerPostMortem).not.toHaveBeenCalled(); + expect(loggerError).not.toHaveBeenCalled(); + }); + + it("still reconciles when the post-mortem read fails", async () => { + ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "stalled", reason: "PodFailed" }, + payloadIssuedAt: new Date("2026-01-01T00:00:00Z"), + }); + }); + readWorkflowRunnerPostMortem.mockRejectedValue(new Error("Kubernetes unavailable")); + + await reconcileWorkflowRunners(); + + expect(events).toContain(`ensure:${secondAttempt.attemptId}`); + expect(recordWorkflowRunnerPostMortem).not.toHaveBeenCalled(); + }); + + it("captures the post-mortem before terminalizing a pre-payload stalled Pod", async () => { + // Ordering matters: terminalizing starts the cleanup that deletes the Pod + // the post-mortem reads. + ensureCurrentWorkflowRunnerResources.mockImplementationOnce((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "stalled", reason: "PodFailed" }, + payloadIssuedAt: null, + }); + }); + failWorkflowRunnerResourceAttempt.mockImplementation(() => { + events.push("fail"); + return Promise.resolve(); + }); + + await reconcileWorkflowRunners(); + + expect(events.indexOf(`postmortem:read:${firstAttempt.attemptId}`)).toBeLessThan( + events.indexOf("fail"), + ); }); it("skips lease work for an attempt that is no longer ready", async () => { diff --git a/test/orchestrator/workflow-runner-store.test.ts b/test/orchestrator/workflow-runner-store.test.ts index 8af9c81..4585a07 100644 --- a/test/orchestrator/workflow-runner-store.test.ts +++ b/test/orchestrator/workflow-runner-store.test.ts @@ -639,6 +639,73 @@ describe.skipIf(sql === null)("workflow runner admission", () => { }); }); + it("records the runner Pod post-mortem exactly once per attempt", async () => { + // The reconciler runs every 30s against a Pod Kubernetes is collecting, so + // a last-write-wins update would replace the first, complete reading with a + // progressively emptier one. + const { claimWorkflowRunnerAttempt, recordWorkflowRunnerPostMortem } = + await import("../../src/orchestrator/workflow-runner-store"); + const job = await queuedWorkflow(61); + const claim = await claimWorkflowRunnerAttempt(job, 600_000, 1, requireSql()); + if (claim.outcome !== "claimed") throw new Error("Expected claim"); + + expect( + await recordWorkflowRunnerPostMortem( + claim.attempt, + { reason: "OOMKilled", exitCode: 137 }, + requireSql(), + ), + ).toBe(true); + expect( + await recordWorkflowRunnerPostMortem(claim.attempt, { reason: "Error" }, requireSql()), + ).toBe(false); + + const [row] = await requireSql()` + SELECT state->'_runnerPostMortem' AS post_mortem FROM workflow_runs + WHERE id = ${claim.attempt.runId} + `; + expect(row.post_mortem).toEqual({ reason: "OOMKilled", exitCode: 137 }); + }); + + it("reports whether an attempt already has a post-mortem on record", async () => { + // Read before the two Kubernetes calls, so a stalled attempt left to lease + // expiry does not re-read its Pod and log on every 30s pass. + const { + claimWorkflowRunnerAttempt, + recordWorkflowRunnerPostMortem, + hasWorkflowRunnerPostMortem, + } = await import("../../src/orchestrator/workflow-runner-store"); + const job = await queuedWorkflow(63); + const claim = await claimWorkflowRunnerAttempt(job, 600_000, 1, requireSql()); + if (claim.outcome !== "claimed") throw new Error("Expected claim"); + + expect(await hasWorkflowRunnerPostMortem(claim.attempt, requireSql())).toBe(false); + await recordWorkflowRunnerPostMortem(claim.attempt, { reason: "OOMKilled" }, requireSql()); + expect(await hasWorkflowRunnerPostMortem(claim.attempt, requireSql())).toBe(true); + expect( + await hasWorkflowRunnerPostMortem( + { runId: claim.attempt.runId, attemptId: crypto.randomUUID() }, + requireSql(), + ), + ).toBe(false); + }); + + it("refuses a post-mortem aimed at a superseded attempt", async () => { + const { claimWorkflowRunnerAttempt, recordWorkflowRunnerPostMortem } = + await import("../../src/orchestrator/workflow-runner-store"); + const job = await queuedWorkflow(62); + const claim = await claimWorkflowRunnerAttempt(job, 600_000, 1, requireSql()); + if (claim.outcome !== "claimed") throw new Error("Expected claim"); + + expect( + await recordWorkflowRunnerPostMortem( + { runId: claim.attempt.runId, attemptId: crypto.randomUUID() }, + { reason: "OOMKilled" }, + requireSql(), + ), + ).toBe(false); + }); + it("extends a startup lease while the runner has not yet been handed its payload", async () => { // Regression: the startup lease is claimed before the Pod exists, so image // pull burns it. The reconciler extends on evidence the Pod is still coming From 72828fcfdeb42cd311b26f8e53131329b3826be1 Mon Sep 17 00:00:00 2001 From: Chris Lee Date: Thu, 10 Sep 2026 05:37:07 +1000 Subject: [PATCH 2/3] fix(orchestrator): keep the post-mortem writable and wire it to both notices Six review findings on the Pod post-mortem. The log tail was sliced at a fixed UTF-16 index, so a cut inside an astral character left a lone surrogate. `JSON.stringify` renders that as a `\udXXX` escape and Postgres rejects it on the `jsonb` cast, verified against Postgres 17 with the store's own `state || $1::jsonb` statement. `capturePodPostMortem` swallows the throw as a warning and writes nothing, so the one-shot fence never closes and every later pass re-reads the Pod and fails identically. The post-mortem was lost for exactly the runs with the most log to show. Unpaired surrogates are now replaced with U+FFFD. `podPostMortemLine` was wired into the lease-expiry notice only, but the reconciler captures for every stalled attempt and a pre-payload one is terminalized by `notifyRunnerStartFailures`. A Pod OOMKilled before registering therefore said "could not start: PodFailed" while the run row held `OOMKilled` and exit 137. That notice now quotes the same bounded fields. Reaching the 256 KB transfer ceiling means the server stopped sending before the runner's final lines, since the 200-line window starts at the oldest of them, so the tail is from the middle of the run. That is now reported in `logError` rather than left to look like the end of the log. The `lastState` fallback read the live container's log next to a replaced container's exit code. The log read now follows the verdict via `previous`. Two JSDoc blocks documenting `capturePodPostMortem` and `recordWorkflowRunnerPostMortem` sat above the wrong function, so the two contracts that matter to callers, "never throws" and the one-shot fence, were invisible on hover. Moved onto the functions they describe. I did not take the line-alignment half of the surrogate suggestion. Advancing the cut to the next newline reads better, but a window holding one long line and one short one would then store the short one and discard 16 KB of context. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TGnjV4sgzrDCVNznUQ1uuv --- docs/operate/observability.md | 6 +- src/k8s/workflow-runner-postmortem.ts | 84 ++++++++++++++++--- src/orchestrator/workflow-expiry-notifier.ts | 8 ++ .../workflow-runner-reconciler.ts | 22 ++--- src/orchestrator/workflow-runner-store.ts | 24 +++--- test/k8s/workflow-runner-postmortem.test.ts | 56 +++++++++++++ .../workflow-expiry-notifier.test.ts | 20 +++++ 7 files changed, 184 insertions(+), 36 deletions(-) diff --git a/docs/operate/observability.md b/docs/operate/observability.md index c92b73c..dc506ae 100644 --- a/docs/operate/observability.md +++ b/docs/operate/observability.md @@ -471,10 +471,10 @@ It exists because everything else is gone by the time anyone asks. Cleanup delet | `exitCode`, `signal` | `137` with `OOMKilled` is the kernel OOM killer. A bare `137` without that reason is an external `SIGKILL`. | | `message` | The container's termination message, when the runtime set one. | | `startedAt`, `finishedAt` | Container lifetime. `finishedAt` should match the abnormal WebSocket close, see below. | -| `logTail` | Last 200 lines of runner stdout, secret-stripped and capped at 16 KB. Empty when `pods/log` RBAC is missing. | -| `logError` | Why `logTail` is empty. A `403` here means the Role is missing `pods/log` `get`, see the deployment RBAC. | +| `logTail` | Last 200 lines of runner stdout, secret-stripped and capped at 16 KB. Empty when `pods/log` RBAC is missing. Unpaired surrogates are replaced with U+FFFD, because a cut inside an astral character would make the row unwritable as `jsonb`. | +| `logError` | Why `logTail` is not the whole story. A `403` means the Role is missing `pods/log` `get`, see the deployment RBAC. A `transfer ceiling` message means the 200-line window exceeded 256 KB, so the server stopped sending before the runner's final lines. | -The same record is persisted to `workflow_runs.state._runnerPostMortem`, so it survives log rotation and is queryable per run. The failure comment quotes only the kubelet reason (`reason`, falling back to `podReason`) and `exitCode`, and shape-checks it against `^[A-Za-z][A-Za-z0-9]{0,63}$` first; `message`, `podMessage` and `logTail` are repository or node content and stay in the controller log. An all-null reading is discarded rather than recorded, so a pass that catches the Pod before kubelet wrote its status does not spend the one-shot slot. +The same record is persisted to `workflow_runs.state._runnerPostMortem`, so it survives log rotation and is queryable per run. Both failure comments quote it, the lease/deadline expiry notice and the runner-start-failure notice, since a Pod that dies before registering is terminalized by the second. Each quotes only the kubelet reason (`reason`, falling back to `podReason`) and `exitCode`, and shape-checks the reason against `^[A-Za-z][A-Za-z0-9]{0,63}$` first; `message`, `podMessage` and `logTail` are repository or node content and stay in the controller log. An all-null reading is discarded rather than recorded, so a pass that catches the Pod before kubelet wrote its status does not spend the one-shot slot. Correlate with the socket: `WebSocket connection closed` carries `kind`, plus `runId` and `attemptId` for a `workflow-runner` socket. Close code `1006` (abnormal, no close frame) at the same second as `finishedAt` is the signature of a runner killed outright rather than one shutting down. diff --git a/src/k8s/workflow-runner-postmortem.ts b/src/k8s/workflow-runner-postmortem.ts index 05ef1b1..b731431 100644 --- a/src/k8s/workflow-runner-postmortem.ts +++ b/src/k8s/workflow-runner-postmortem.ts @@ -17,11 +17,15 @@ const LOG_TAIL_BYTES = 16_384; // A ceiling on the transfer, not the tail. `limitBytes` stops the server after N // bytes of a stream that arrives oldest-first, so setting it to LOG_TAIL_BYTES // would discard the newest lines, which is exactly the crash. Kept well above -// the tail so the local slice is what decides, while one pathological line still -// cannot pull an unbounded body into the controller. +// the tail so the local slice normally decides, while one pathological line +// still cannot pull an unbounded body into the controller. When the 200-line +// window does exceed it the newest lines are lost, which `logError` reports. const LOG_READ_CEILING_BYTES = 262_144; // A Kubernetes error body can be a full HTML page; only the head identifies it. const LOG_ERROR_CHARS = 200; +// A surrogate with no partner. `slice` cuts at a code-unit index and can land +// inside an astral character, and agent stdout carries plenty of those. +const LONE_SURROGATE = /[\uD800-\uDBFF](?![\uDC00-\uDFFF])|(? c.name === RUNNER_CONTAINER); + const current = status?.state?.terminated; + if (current !== undefined) return { state: current, fromLastState: false }; // `lastState` holds the exit of a container kubelet already replaced. The // runner spec uses restartPolicy Never so it is normally empty, but reading // it costs nothing and covers a restart the spec did not intend. - return status?.state?.terminated ?? status?.lastState?.terminated; + const replaced = status?.lastState?.terminated; + return { state: replaced, fromLastState: replaced !== undefined }; +} + +/** + * The newest bytes of the log, bounded and safe to store. + * + * The cut is at a fixed code-unit index, so it can land inside an astral + * character, and agent stdout is full of them. `JSON.stringify` renders the + * resulting lone surrogate as a `\udXXX` escape, which Postgres rejects when + * the patch is cast to `jsonb`. The caller swallows that throw and writes + * nothing, so the one-shot fence never closes and every later pass re-reads the + * Pod and fails identically: the post-mortem would be lost for exactly the runs + * with the most log to show. Substituting U+FFFD keeps the bytes and the write. + * + * The first line is left as the fragment it is. Advancing to the next newline + * would read better, but a run whose window holds one long line and one short + * one would then store the short one and discard 16 KB of context. + */ +function boundedTail(body: string): string { + return body.slice(-LOG_TAIL_BYTES).replace(LONE_SURROGATE, "�"); } /** The client deserializes these to `Date`; raw API JSON yields strings. */ @@ -63,6 +103,7 @@ function isoOrNull(value: unknown): string | null { async function readLogTail( podName: string, namespace: string, + previous: boolean, ): Promise<{ readonly tail: string; readonly error: string | null }> { try { const raw = await loadKubernetesClient().core.readNamespacedPodLog({ @@ -71,13 +112,26 @@ async function readLogTail( container: RUNNER_CONTAINER, tailLines: LOG_TAIL_LINES, limitBytes: LOG_READ_CEILING_BYTES, + ...(previous ? { previous: true } : {}), }); // Runner stdout echoes repository content and may carry a token the agent // printed, so it is stripped before it reaches the controller log or the // run row. Same rule as every other output path (security invariant #2). // Sliced from the end: the last lines before the kill are the diagnostic // ones. redactSecrets only deletes bytes, so this caps the redacted text. - return { tail: redactSecrets(raw).body.slice(-LOG_TAIL_BYTES), error: null }; + // + // The ceiling applies to the whole 200-line window, which starts at the + // oldest of those lines, so reaching it means the server stopped sending + // before the runner's final output. The tail below is then from the middle + // of the run, and saying nothing would let a reader take its last line for + // the last line the runner wrote. + const truncated = Buffer.byteLength(raw, "utf8") >= LOG_READ_CEILING_BYTES; + return { + tail: boundedTail(redactSecrets(raw).body), + error: truncated + ? `log read hit the ${LOG_READ_CEILING_BYTES}-byte transfer ceiling, so the runner's final lines are missing` + : null, + }; } catch (err) { const message = err instanceof Error ? err.message : String(err); return { tail: "", error: message.slice(0, LOG_ERROR_CHARS) }; @@ -95,12 +149,11 @@ function podFields(pod: V1Pod): Pick { - const state = terminatedState(pod); return { exitCode: state?.exitCode ?? null, reason: state?.reason ?? null, @@ -131,6 +184,17 @@ export async function readWorkflowRunnerPostMortem(attempt: { } catch { return null; } - const { tail, error } = await readLogTail(podName, namespace); - return { podName, ...podFields(pod), ...containerFields(pod), logTail: tail, logError: error }; + // One container, one story: when the verdict comes from a container kubelet + // already replaced, the running container's log belongs to a different + // process, so the read follows the verdict rather than pairing an exit code + // with someone else's output. + const terminated = terminatedState(pod); + const { tail, error } = await readLogTail(podName, namespace, terminated.fromLastState); + return { + podName, + ...podFields(pod), + ...containerFields(terminated.state), + logTail: tail, + logError: error, + }; } diff --git a/src/orchestrator/workflow-expiry-notifier.ts b/src/orchestrator/workflow-expiry-notifier.ts index 51537e9..25b8984 100644 --- a/src/orchestrator/workflow-expiry-notifier.ts +++ b/src/orchestrator/workflow-expiry-notifier.ts @@ -315,11 +315,19 @@ export async function notifyRunnerStartFailures(rows: readonly WorkflowRunRow[]) humanMessage: (row) => { const reason = row.state["failedReason"]; const detail = typeof reason === "string" ? reason : "Workflow runner configuration failed"; + // The reconciler captures a post-mortem for every stalled attempt, and a + // pre-payload one lands here rather than in the expiry notice. Without + // this line a Pod that was OOMKilled before registering reads as + // "could not start: PodFailed" while the run row already holds the reason + // and exit code, which is the commonest shape for an under-resourced + // runner and the one an operator most needs named. + const postMortem = podPostMortemLine(row); return [ "❌ **Workflow runner could not start**", "", `${detail}. The database marked the workflow failed and released its in-flight lock.`, "", + ...(postMortem === null ? [] : [postMortem, ""]), "Fix the runner deployment configuration, then re-trigger the workflow.", ].join("\n"); }, diff --git a/src/orchestrator/workflow-runner-reconciler.ts b/src/orchestrator/workflow-runner-reconciler.ts index abb2109..80d18e4 100644 --- a/src/orchestrator/workflow-runner-reconciler.ts +++ b/src/orchestrator/workflow-runner-reconciler.ts @@ -25,17 +25,6 @@ import { type WorkflowRunnerAttempt, } from "./workflow-runner-store"; -/** - * Persist and log why the runner Pod died, at most once per attempt. - * - * This is the only durable record. The Pod, its terminated container status and - * its logs are deleted on cleanup, so by the time anyone reads the failure - * comment there is nothing left to inspect, and "the runner stopped renewing" - * cannot distinguish an OOMKill from a crash from a node eviction. - * - * Never throws: a post-mortem that cannot be read must not derail the failure - * path that prompted it. - */ /** * Whether the reading says anything the failure comment or an operator could * use. A pass that catches the Pod before kubelet has written any status reads @@ -51,6 +40,17 @@ function isInformative(postMortem: RunnerPodPostMortem): boolean { ); } +/** + * Persist and log why the runner Pod died, at most once per attempt. + * + * This is the only durable record. The Pod, its terminated container status and + * its logs are deleted on cleanup, so by the time anyone reads the failure + * comment there is nothing left to inspect, and "the runner stopped renewing" + * cannot distinguish an OOMKill from a crash from a node eviction. + * + * Never throws: a post-mortem that cannot be read must not derail the failure + * path that prompted it. + */ async function capturePodPostMortem( attempt: WorkflowRunnerAttempt, startupReason: string, diff --git a/src/orchestrator/workflow-runner-store.ts b/src/orchestrator/workflow-runner-store.ts index 83648f5..e5da389 100644 --- a/src/orchestrator/workflow-runner-store.ts +++ b/src/orchestrator/workflow-runner-store.ts @@ -771,18 +771,6 @@ export async function extendWorkflowRunnerStartupLease( return rows[0] !== undefined; } -/** - * Record why the runner Pod died, once per attempt. - * - * Fenced on the key being absent, so the 30s reconcile loop stores the first - * reading instead of overwriting it with a progressively emptier one as - * Kubernetes garbage-collects the Pod, and on `attempt_id`, so a superseded - * attempt cannot stamp the current one. True only for the write that landed, - * which is also the caller's cue to emit the log line exactly once. - * - * `jsonb_exists` rather than the `?` operator: `?` is a placeholder marker in - * enough SQL layers that the function form is the safer spelling here. - */ /** * Whether this attempt already has a post-mortem on record. * @@ -805,6 +793,18 @@ export async function hasWorkflowRunnerPostMortem( return rows[0]?.present === true; } +/** + * Record why the runner Pod died, once per attempt. + * + * Fenced on the key being absent, so the 30s reconcile loop stores the first + * reading instead of overwriting it with a progressively emptier one as + * Kubernetes garbage-collects the Pod, and on `attempt_id`, so a superseded + * attempt cannot stamp the current one. True only for the write that landed, + * which is also the caller's cue to emit the log line exactly once. + * + * `jsonb_exists` rather than the `?` operator: `?` is a placeholder marker in + * enough SQL layers that the function form is the safer spelling here. + */ export async function recordWorkflowRunnerPostMortem( attempt: { readonly runId: string; readonly attemptId: string }, postMortem: Record, diff --git a/test/k8s/workflow-runner-postmortem.test.ts b/test/k8s/workflow-runner-postmortem.test.ts index 6f5a60b..bcf31ed 100644 --- a/test/k8s/workflow-runner-postmortem.test.ts +++ b/test/k8s/workflow-runner-postmortem.test.ts @@ -10,6 +10,7 @@ const readNamespacedPodLog = mock( container?: string; tailLines?: number; limitBytes?: number; + previous?: boolean; }): Promise => Promise.resolve(""), ); const core = { readNamespacedPod, readNamespacedPodLog }; @@ -200,6 +201,49 @@ describe("readWorkflowRunnerPostMortem", () => { expect(postMortem?.logError).toContain("403"); }); + // A cut at a fixed code-unit index can split an astral character. The lone + // surrogate left behind is escaped by JSON.stringify as \udXXX, which + // Postgres rejects on the jsonb cast, and the caller swallows the throw + // without closing its one-shot fence: the post-mortem is then lost for every + // pass, on exactly the runs with the most log to show. + it("stores a well-formed tail when the cut splits an astral character", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + // One emoji is two code units. Padding to an odd offset from the cut point + // guarantees the 16384-from-the-end boundary lands between them. + readNamespacedPodLog.mockImplementation(() => + Promise.resolve(`${"o".repeat(4_000)}\u{1F50D}${"y".repeat(16_383)}`), + ); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + const tail = postMortem?.logTail ?? ""; + + expect(tail.length).toBe(16_384); + // The real assertion: it survives the round trip the store performs. + expect(() => JSON.parse(JSON.stringify({ logTail: tail }))).not.toThrow(); + expect(/[\uD800-\uDFFF]/.test(tail)).toBe(false); + expect(JSON.stringify(tail)).not.toContain("\\ud"); + }); + + // `limitBytes` stops the server partway through a window that starts at the + // oldest of the 200 lines, so hitting it means the final lines were never + // sent and the tail is from the middle of the run. + it("reports that the transfer ceiling cut the log short", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => Promise.resolve("z".repeat(262_144))); + + const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); + + expect(postMortem?.logTail.length).toBe(16_384); + expect(postMortem?.logError).toContain("transfer ceiling"); + }); + + it("leaves logError null when the log fits under the ceiling", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => Promise.resolve("short log\n")); + + expect((await readWorkflowRunnerPostMortem({ attemptId }))?.logError).toBeNull(); + }); + it("falls back to lastState for a container kubelet already replaced", async () => { readNamespacedPod.mockImplementation(() => Promise.resolve({ @@ -220,6 +264,18 @@ describe("readWorkflowRunnerPostMortem", () => { expect(postMortem?.exitCode).toBe(1); expect(postMortem?.reason).toBe("Error"); + // The verdict belongs to the container kubelet replaced, so the log must + // come from that container too. Without `previous`, the record would pair + // one container's exit code with another container's output. + expect(readNamespacedPodLog.mock.calls[0]?.[0]).toMatchObject({ previous: true }); + }); + + it("reads the live container's log when the verdict is its own", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + + await readWorkflowRunnerPostMortem({ attemptId }); + + expect(readNamespacedPodLog.mock.calls[0]?.[0]).not.toHaveProperty("previous"); }); it("returns null once the Pod is gone", async () => { diff --git a/test/orchestrator/workflow-expiry-notifier.test.ts b/test/orchestrator/workflow-expiry-notifier.test.ts index e004bb7..6436456 100644 --- a/test/orchestrator/workflow-expiry-notifier.test.ts +++ b/test/orchestrator/workflow-expiry-notifier.test.ts @@ -322,6 +322,26 @@ describe("workflow expiry notifier", () => { expect(markWorkflowFailureNotified).toHaveBeenCalledTimes(1); }); + // The reconciler captures a post-mortem for every stalled attempt, and a + // pre-payload one is terminalized here rather than at lease expiry. Without + // this the comment reads "could not start: PodFailed" while the run row + // already holds OOMKilled and exit 137, the commonest under-resourced shape. + it("names the Pod's cause of death on a runner-start failure", async () => { + const failed = row("failed", null, "Runner Pod could not start: PodFailed"); + failed.state = { + failedReason: "Runner Pod could not start: PodFailed", + _runnerPostMortem: { reason: "OOMKilled", exitCode: 137, logTail: "secret repo content" }, + }; + + await notifyRunnerStartFailures([failed] as never); + + const call = setState.mock.calls[0] as unknown as [unknown, { humanMessage: string }]; + expect(call[1].humanMessage).toContain("OOMKilled"); + expect(call[1].humanMessage).toContain("exit code 137"); + // Repository content stays in the controller log, never on a public comment. + expect(call[1].humanMessage).not.toContain("secret repo content"); + }); + it("projects and receipts a queued dispatch expiry", async () => { const failed = row("dispatch-expired", null, "workflow dispatch deadline expired"); failed.attempt_id = null; From 97711ae9b1e93c50406c3fd8945567cb86982e76 Mon Sep 17 00:00:00 2001 From: Chris Lee Date: Thu, 10 Sep 2026 06:08:18 +1000 Subject: [PATCH 3/3] fix(orchestrator): capture a clean exit, and cap the log tail in bytes Round two review findings on the Pod post-mortem. A runner whose process returns 0 without ever sending a result was the one silent death this feature could not explain. `classifyPodStartup` maps phase `Succeeded` to `running`, so such an attempt stayed classified running on every pass, captured nothing, and had its Pod and log deleted at lease-expiry cleanup. `RunnerPodStartup`'s running variant now carries `terminal`, and the reconciler treats a terminal Pod as dead. Reaching a still-active attempt means no result was reported, so there is no healthy run to misreport. The 16 KB tail cap counted UTF-16 code units while the constant, the comment, the observability table and the ceiling check 34 lines below all meant bytes. Emoji-heavy agent output would have stored about four times the budget. The cut is now taken in UTF-8 and advanced past any continuation bytes, which also makes the result well-formed by construction and retires the surrogate scrub the previous commit added: skipping the partial character keeps the budget exact, where decoding it would expand each stray byte into a three-byte U+FFFD. A refused or failed Pod-status read returned null with nothing logged, so it repeated on every pass without evidence. Now logged at debug. `_runnerPostMortem` was added to `CONTROLLER_RESERVED_STATE_KEYS` without extending the test that iterates them, leaving the security argument for the key unenforced against a refactor. I did not widen `isInformative` to accept a `logError`-only reading. The suggestion would defeat the fence it feeds: a permanent `pods/log` 403 on a pass that catches the Pod before kubelet wrote any status would then win the one-shot slot and lock out the later pass holding the real verdict. The other proposed fields are unreachable without `exitCode`, which is required on a terminated container state. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TGnjV4sgzrDCVNznUQ1uuv --- docs/operate/observability.md | 6 +-- src/k8s/workflow-runner-postmortem.ts | 46 +++++++++++++------ src/k8s/workflow-runner-spawner.ts | 14 +++++- .../workflow-runner-reconciler.ts | 18 +++++++- test/k8s/workflow-runner-postmortem.test.ts | 17 ++++++- test/k8s/workflow-runner-spawner.test.ts | 13 +++++- .../workflow-runner-reconciler.test.ts | 43 ++++++++++++++++- .../workflow-runner-resources.test.ts | 6 ++- test/shared/workflow-runner-messages.test.ts | 2 +- 9 files changed, 137 insertions(+), 28 deletions(-) diff --git a/docs/operate/observability.md b/docs/operate/observability.md index dc506ae..2ca5256 100644 --- a/docs/operate/observability.md +++ b/docs/operate/observability.md @@ -458,20 +458,20 @@ A run of consecutive `startupPhase=starting` lines for one `attemptId` measures ## Workflow runner Pod post-mortem -`event: "workflow_runner_pod_died"` (`src/orchestrator/workflow-runner-reconciler.ts#capturePodPostMortem`) is logged at `error` the first time a reconciler pass sees a `stalled` Pod for an attempt, and at most once per attempt. It is the answer to "why did the lease expire", which the lease-expiry notice itself cannot give. +`event: "workflow_runner_pod_died"` (`src/orchestrator/workflow-runner-reconciler.ts#capturePodPostMortem`) is logged at `error` the first time a reconciler pass sees a dead Pod for an attempt, and at most once per attempt. Dead means either a `stalled` startup phase or a Pod that reached `Succeeded`: under `restartPolicy: Never` a runner whose process returns 0 without ever sending a result lands in `Succeeded`, which startup classifies as `running`, and reaching an attempt that is still active means no result was reported. It is the answer to "why did the lease expire", which the lease-expiry notice itself cannot give. It exists because everything else is gone by the time anyone asks. Cleanup deletes the Pod, and with it the terminated container status and the container log, within seconds of the run being terminalized. A cluster log pipeline is not a dependable second copy: on this deployment the Datadog Logs **aggregate** API counted 547 lines for a dead runner while the **search** API returned zero retrievable events, and no container metrics were collected at all. | Field | Meaning | | ----------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `podName`, `podPhase` | Which Pod, and its phase at capture (`Failed` for a container that exited non-zero under `restartPolicy: Never`). | +| `podName`, `podPhase` | Which Pod, and its phase at capture. `Failed` is a non-zero exit under `restartPolicy: Never`; `Succeeded` is a clean exit that never reported a result; `Pending` is a container that never ran. | | `reason` | Kubelet's **container** termination reason. `OOMKilled` is the memory limit; `Error` is a non-zero exit. | | `podReason`, `podMessage` | The **Pod**-level verdict, which is where a node decision lands: `Evicted` for node pressure such as a filled ephemeral-storage limit, `DeadlineExceeded` for `activeDeadlineSeconds`. A container that never ran leaves `reason` null and only these set. | | `runId`, `attemptId`, `workflowName`, `startupReason` | Attempt identity plus the blocker the reconciler last saw, so the line joins to the `startupPhase` trail above. | | `exitCode`, `signal` | `137` with `OOMKilled` is the kernel OOM killer. A bare `137` without that reason is an external `SIGKILL`. | | `message` | The container's termination message, when the runtime set one. | | `startedAt`, `finishedAt` | Container lifetime. `finishedAt` should match the abnormal WebSocket close, see below. | -| `logTail` | Last 200 lines of runner stdout, secret-stripped and capped at 16 KB. Empty when `pods/log` RBAC is missing. Unpaired surrogates are replaced with U+FFFD, because a cut inside an astral character would make the row unwritable as `jsonb`. | +| `logTail` | Last 200 lines of runner stdout, secret-stripped and capped at 16 KB, measured in UTF-8 bytes. The cut starts on a character boundary, because a partial character would make the row unwritable as `jsonb`. Empty when `pods/log` RBAC is missing. | | `logError` | Why `logTail` is not the whole story. A `403` means the Role is missing `pods/log` `get`, see the deployment RBAC. A `transfer ceiling` message means the 200-line window exceeded 256 KB, so the server stopped sending before the runner's final lines. | The same record is persisted to `workflow_runs.state._runnerPostMortem`, so it survives log rotation and is queryable per run. Both failure comments quote it, the lease/deadline expiry notice and the runner-start-failure notice, since a Pod that dies before registering is terminalized by the second. Each quotes only the kubelet reason (`reason`, falling back to `podReason`) and `exitCode`, and shape-checks the reason against `^[A-Za-z][A-Za-z0-9]{0,63}$` first; `message`, `podMessage` and `logTail` are repository or node content and stay in the controller log. An all-null reading is discarded rather than recorded, so a pass that catches the Pod before kubelet wrote its status does not spend the one-shot slot. diff --git a/src/k8s/workflow-runner-postmortem.ts b/src/k8s/workflow-runner-postmortem.ts index b731431..21eba51 100644 --- a/src/k8s/workflow-runner-postmortem.ts +++ b/src/k8s/workflow-runner-postmortem.ts @@ -1,6 +1,7 @@ import type { V1ContainerStateTerminated, V1Pod } from "@kubernetes/client-node"; import { config } from "../config"; +import { logger } from "../logger"; import { redactSecrets } from "../utils/sanitize"; import { loadKubernetesClient } from "./ephemeral-daemon-spawner"; import { workflowRunnerResourceNames } from "./workflow-runner-spawner"; @@ -23,9 +24,6 @@ const LOG_TAIL_BYTES = 16_384; const LOG_READ_CEILING_BYTES = 262_144; // A Kubernetes error body can be a full HTML page; only the head identifies it. const LOG_ERROR_CHARS = 200; -// A surrogate with no partner. `slice` cuts at a code-unit index and can land -// inside an astral character, and agent stdout carries plenty of those. -const LONE_SURROGATE = /[\uD800-\uDBFF](?![\uDC00-\uDFFF])|(? { // only moment the controller holds both the evidence and a live Pod: the // lease has minutes left and neither the terminalization below nor its // cleanup has deleted anything yet. - if (result.startup.phase === "stalled") { + // + // `Succeeded` counts as dead here even though startup calls it running. + // Under `restartPolicy: Never` a runner whose process returns 0 without + // ever sending a result lands there, stays classified running on every + // pass, and has its Pod and log deleted at lease-expiry cleanup. That is + // the one silent death the expiry notice could not explain, and reaching + // this attempt at all means no result was reported: an attempt that + // finished normally is no longer active. + const dead = + result.startup.phase === "stalled" + ? result.startup.reason + : result.startup.phase === "running" && result.startup.terminal + ? "PodSucceeded without a reported result" + : null; + if (dead !== null) { // eslint-disable-next-line no-await-in-loop -- one post-mortem per attempt, in order - await capturePodPostMortem(attempt, result.startup.reason); + await capturePodPostMortem(attempt, dead); } // Startup handling only. Once the payload is issued the runner holds its diff --git a/test/k8s/workflow-runner-postmortem.test.ts b/test/k8s/workflow-runner-postmortem.test.ts index bcf31ed..6da3992 100644 --- a/test/k8s/workflow-runner-postmortem.test.ts +++ b/test/k8s/workflow-runner-postmortem.test.ts @@ -217,11 +217,26 @@ describe("readWorkflowRunnerPostMortem", () => { const postMortem = await readWorkflowRunnerPostMortem({ attemptId }); const tail = postMortem?.logTail ?? ""; - expect(tail.length).toBe(16_384); // The real assertion: it survives the round trip the store performs. expect(() => JSON.parse(JSON.stringify({ logTail: tail }))).not.toThrow(); expect(/[\uD800-\uDFFF]/.test(tail)).toBe(false); expect(JSON.stringify(tail)).not.toContain("\\ud"); + // The cap is a byte budget, so a code-unit slice of astral content cannot + // quietly store four times it. + expect(Buffer.byteLength(tail, "utf8")).toBeLessThanOrEqual(16_384); + }); + + // `slice` counts UTF-16 code units, and an astral character is two of them + // but four bytes, so a code-unit cap would store roughly 4x the budget. + it("caps the tail in bytes, not code units", async () => { + readNamespacedPod.mockImplementation(() => Promise.resolve(oomKilledPod())); + readNamespacedPodLog.mockImplementation(() => Promise.resolve("\u{1F50D}".repeat(20_000))); + + const tail = (await readWorkflowRunnerPostMortem({ attemptId }))?.logTail ?? ""; + + expect(Buffer.byteLength(tail, "utf8")).toBeLessThanOrEqual(16_384); + expect(Buffer.byteLength(tail, "utf8")).toBeGreaterThan(16_000); + expect(/[\uD800-\uDFFF]/.test(tail.replace(/\u{1F50D}/gu, ""))).toBe(false); }); // `limitBytes` stops the server partway through a window that starts at the diff --git a/test/k8s/workflow-runner-spawner.test.ts b/test/k8s/workflow-runner-spawner.test.ts index a2b154e..521bb65 100644 --- a/test/k8s/workflow-runner-spawner.test.ts +++ b/test/k8s/workflow-runner-spawner.test.ts @@ -892,8 +892,17 @@ describe("workflow runner Pod startup classification", () => { }); it("reads a started Pod as running", () => { - expect(classifyPodStartup({ status: { phase: "Running" } })).toEqual({ phase: "running" }); - expect(classifyPodStartup({ status: { phase: "Succeeded" } })).toEqual({ phase: "running" }); + expect(classifyPodStartup({ status: { phase: "Running" } })).toEqual({ + phase: "running", + terminal: false, + }); + // Succeeded is not a startup problem, but it is terminal: under + // restartPolicy Never nothing further will come from this Pod, which is + // what lets the reconciler catch a runner that exited 0 without a result. + expect(classifyPodStartup({ status: { phase: "Succeeded" } })).toEqual({ + phase: "running", + terminal: true, + }); }); it("reads waiting reasons no retry resolves as stalled", () => { diff --git a/test/orchestrator/workflow-runner-reconciler.test.ts b/test/orchestrator/workflow-runner-reconciler.test.ts index 7b2cc78..9cc5e56 100644 --- a/test/orchestrator/workflow-runner-reconciler.test.ts +++ b/test/orchestrator/workflow-runner-reconciler.test.ts @@ -36,7 +36,7 @@ const ensureCurrentWorkflowRunnerResources = mock((input: { attempt: { attemptId events.push(`ensure:${input.attempt.attemptId}`); return Promise.resolve({ state: "ready", - startup: { phase: "running" }, + startup: { phase: "running", terminal: false }, payloadIssuedAt: null, } as const); }); @@ -166,7 +166,7 @@ describe("workflow runner reconciliation", () => { events.push(`ensure:${input.attempt.attemptId}`); return Promise.resolve({ state: "ready", - startup: { phase: "running" }, + startup: { phase: "running", terminal: false }, payloadIssuedAt: null, }); }); @@ -406,6 +406,45 @@ describe("workflow runner reconciliation", () => { ); }); + // Under restartPolicy Never a runner whose process returns 0 without sending + // a result lands in phase Succeeded, which startup classifies as running. It + // would otherwise stay that way on every pass, and its Pod and log would be + // deleted at lease-expiry cleanup, leaving the operator the bare "stopped + // renewing" notice this feature exists to replace. + it("captures the post-mortem for a runner that exited 0 without a result", async () => { + ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "running", terminal: true }, + payloadIssuedAt: new Date().toISOString(), + }); + }); + + await reconcileWorkflowRunners(); + + expect(events).toContain(`postmortem:read:${firstAttempt.attemptId}`); + expect(recordWorkflowRunnerPostMortem).toHaveBeenCalled(); + // Still not a start failure: the payload was issued, so terminalizing here + // would replace the inspect-the-repository warning with "could not start". + expect(failWorkflowRunnerResourceAttempt).not.toHaveBeenCalled(); + }); + + it("leaves a healthy running Pod alone", async () => { + ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { + events.push(`ensure:${input.attempt.attemptId}`); + return Promise.resolve({ + state: "ready", + startup: { phase: "running", terminal: false }, + payloadIssuedAt: new Date().toISOString(), + }); + }); + + await reconcileWorkflowRunners(); + + expect(recordWorkflowRunnerPostMortem).not.toHaveBeenCalled(); + }); + it("skips lease work for an attempt that is no longer ready", async () => { ensureCurrentWorkflowRunnerResources.mockImplementation((input) => { events.push(`ensure:${input.attempt.attemptId}`); diff --git a/test/orchestrator/workflow-runner-resources.test.ts b/test/orchestrator/workflow-runner-resources.test.ts index 5332959..62f667e 100644 --- a/test/orchestrator/workflow-runner-resources.test.ts +++ b/test/orchestrator/workflow-runner-resources.test.ts @@ -11,7 +11,9 @@ const attempt = { workflowName: "review" as const, attemptDeadlineAt: new Date("2026-08-23T04:10:00Z"), }; -const ensureWorkflowRunnerResources = mock(() => Promise.resolve({ phase: "running" as const })); +const ensureWorkflowRunnerResources = mock(() => + Promise.resolve({ phase: "running" as const, terminal: false }), +); const deleteWorkflowRunnerResources = mock(() => Promise.resolve(true)); const getWorkflowRunnerRegistrationState = mock(() => Promise.resolve({ state: "ready" as const, attempt, payloadIssuedAt: null }), @@ -44,7 +46,7 @@ describe("workflow runner resource operation ordering", () => { beforeEach(() => { resetWorkflowRunnerResourceChainsForTests(); ensureWorkflowRunnerResources.mockReset(); - ensureWorkflowRunnerResources.mockResolvedValue({ phase: "running" }); + ensureWorkflowRunnerResources.mockResolvedValue({ phase: "running", terminal: false }); deleteWorkflowRunnerResources.mockReset(); deleteWorkflowRunnerResources.mockResolvedValue(true); getWorkflowRunnerRegistrationState.mockReset(); diff --git a/test/shared/workflow-runner-messages.test.ts b/test/shared/workflow-runner-messages.test.ts index 3720b9b..37a0b64 100644 --- a/test/shared/workflow-runner-messages.test.ts +++ b/test/shared/workflow-runner-messages.test.ts @@ -228,7 +228,7 @@ describe("HandlerResultSchema daemon actions", () => { describe("workflow runner outbound bounds", () => { it("rejects controller-reserved state keys on every runner-owned state path", () => { - for (const key of ["_configNotice", "_lastHumanMessage"]) { + for (const key of ["_configNotice", "_lastHumanMessage", "_runnerPostMortem"]) { expect(() => WorkflowRunnerCommandSchema.parse({ type: "set-state",