feat(observability): structured pipeline.stage events with delta_ms for runPipeline

[chrisleekr]

Finding

Inside runPipeline (src/core/pipeline.ts:273) only one stage is timed end-to-end. The agent invocation captures startTime = Date.now() at src/core/executor.ts:230 and emits a structured durationMs on the Claude Agent SDK execution completed line at src/core/executor.ts:436-src/core/executor.ts:447. Every other stage logs completion without a duration: Created tracking comment at src/core/tracking-comment.ts:151, the clone-then-config pair Cloning repository at src/core/checkout.ts:59 → Repository checked out and git configured at src/core/checkout.ts:97 (no cloneDurationMs), and Fetched PR data via GraphQL at src/core/fetcher.ts:487. The terminal Request processing completed line at src/core/pipeline.ts:471 reports only the agent's durationMs; the pipeline's own wall-clock is not measured. The error path at src/core/pipeline.ts:541 reports no duration at all. One layer up, the daemon's job:result reports a single bag Date.now() - job.startedAt at src/daemon/job-executor.ts:402 and src/daemon/job-executor.ts:426 with no stage breakdown.

The codebase already has a well-formed model for what good looks like. The ship workflow defines a Zod-validated event schema with delta_ms (per-event wall clock) and wall_clock_ms (cumulative) at src/workflows/ship/log-fields.ts:33-src/workflows/ship/log-fields.ts:53 and a typed event-key constant SHIP_LOG_EVENTS starting at src/workflows/ship/log-fields.ts:70; the contract is documented in docs/operate/observability.md under "Ship workflow log fields" (the delta_ms row at docs/operate/observability.md:54). Extending that pattern (a sibling src/core/log-fields.ts plus structured pipeline.started / pipeline.stage / pipeline.completed events emitted inside runPipeline) closes the attribution gap with a small additive change: no new dependency, no architectural refactor, no behavior shift, just structured fields added at existing log sites plus a single wall_clock_ms total.

The improvement is operationally load-bearing. Today an operator looking at a slow request can answer "how long did the agent take" but cannot answer "why was the pipeline slow", because the gap between job-executor.ts's outer durationMs and executor.ts's inner durationMs is unaccounted-for time that could plausibly be a slow shallow clone (config.cloneDepth), a paginated GraphQL fan-out tripping retryWithBackoff (src/core/fetcher.ts:472-src/core/fetcher.ts:476), a tracking-comment retry storm, or a workspace cleanup hang. Per-stage delta_ms makes that gap diagnosable in the same JSON log stream every other line lives in, keyed by the existing deliveryId correlation.

Diagram

flowchart LR
    subgraph Today["Today: only the agent stage is timed"]
        direction TB
        T1[createTrackingComment<br/>retries, no delta]:::dark
        T2[resolveGithubToken<br/>no delta]:::dark
        T3[fetchGitHubData<br/>retries, no delta]:::dark
        T4[buildPrompt<br/>no delta]:::dark
        T5[checkoutRepo<br/>clone, no delta]:::dark
        T6[executeAgent<br/>durationMs reported]:::lit
        T7[finalizeTrackingComment<br/>retries, no delta]:::dark
        T8[cleanup<br/>no delta]:::dark
        T1 --> T2 --> T3 --> T4 --> T5 --> T6 --> T7 --> T8
        T8 --> TR[Request processing completed<br/>logs only agent durationMs<br/>no pipeline wall clock]:::dark
    end

    subgraph Proposed["Proposed: pipeline.stage events with delta_ms"]
        direction TB
        P0[pipeline.started<br/>t0 captured]:::lit
        P1[pipeline.stage<br/>stage=trackingComment.create<br/>delta_ms]:::lit
        P2[pipeline.stage<br/>stage=token.resolve<br/>delta_ms]:::lit
        P3[pipeline.stage<br/>stage=github.fetch<br/>delta_ms]:::lit
        P4[pipeline.stage<br/>stage=prompt.build<br/>delta_ms]:::lit
        P5[pipeline.stage<br/>stage=repo.clone<br/>delta_ms]:::lit
        P6[pipeline.stage<br/>stage=executor.invoke<br/>delta_ms]:::lit
        P7[pipeline.stage<br/>stage=trackingComment.finalize<br/>delta_ms]:::lit
        P8[pipeline.stage<br/>stage=workspace.cleanup<br/>delta_ms]:::lit
        P9[pipeline.completed<br/>wall_clock_ms]:::lit
        P0 --> P1 --> P2 --> P3 --> P4 --> P5 --> P6 --> P7 --> P8 --> P9
    end

    classDef dark fill:#7b241c;color:#ffffff
    classDef lit fill:#196f3d;color:#ffffff

Loading

Rationale

Three concrete payoffs.

1. Diagnose slow requests by stage. The RED method (Rate, Errors, Duration), originally formalised by Tom Wilkie for microservice SRE, is the canonical model for request-driven services and demands percentile latency broken down per logical step. Today the bot can compute p50/p90/p99 on the agent's durationMs and on the daemon's outer job durationMs, but everything in between (clone, fetch, prompt build, retry-with-backoff windows, finalise, cleanup) is dark. Slow-request triage degrades to reading raw stack traces. Per-stage delta_ms collapses that into a Datadog/Loki query like event:"pipeline.stage" stage:"repo.clone" delta_ms:>5000 that points at the slow stage directly.

2. Detect regressions in CI and at runtime. A dependency bump that doubles octokit.graphql.paginate throughput cost (the three-way fan-out at src/core/fetcher.ts:472-src/core/fetcher.ts:476), a retryWithBackoff storm caused by a transient GitHub 5xx, or a sudden git-clone slowdown on a large repo all look the same today, a vague "Request processing completed" line with the agent's durationMs unchanged but the daemon's outer durationMs higher. A per-stage histogram surfaces each as an isolated regression.

3. Schema parity, zero new dependencies. The ship workflow's delta_ms / wall_clock_ms / typed event-key pattern at src/workflows/ship/log-fields.ts:33-src/workflows/ship/log-fields.ts:80 is already the project's stated convention (documented at docs/operate/observability.md:54). Mirroring it into src/core/ keeps the field taxonomy uniform: aggregations and dashboards can use a single shared field name across both ship-iteration and core-pipeline events. No new npm dependency (preserving CLAUDE.md's "No new npm dependencies" rule), no architectural change, no behaviour shift, just enriched payloads on lines already emitted plus a typed schema in a new file alongside the existing one.

References

Internal:

• src/core/pipeline.ts:273 — runPipeline entry; no pipelineStartedAt captured, no pipeline.started event.
• src/core/pipeline.ts:471 — terminal "Request processing completed" log on success; reports only the agent's durationMs, no pipeline wall-clock.
• src/core/pipeline.ts:541 — terminal "Request processing failed" error log; no duration at all.
• src/core/executor.ts:230 — startTime = Date.now() for agent execution; only stage with a measured duration.
• src/core/executor.ts:436-src/core/executor.ts:447 — "Claude Agent SDK execution completed" line emitting durationMs, the model for what every other stage should emit.
• src/core/tracking-comment.ts:151 — "Created tracking comment" line: no delta_ms despite a retry-wrapped call site.
• src/core/checkout.ts:59 — "Cloning repository" start log; never paired with a duration on completion.
• src/core/checkout.ts:97 — "Repository checked out and git configured" log; would be the natural site for cloneDurationMs.
• src/core/fetcher.ts:487 — "Fetched PR data via GraphQL" log; counts comments/reviews/changedFiles but not fetch duration despite a three-way Promise.all fan-out.
• src/daemon/job-executor.ts:402 and src/daemon/job-executor.ts:426 — daemon-side outer durationMs; single bag, no breakdown.
• src/workflows/ship/log-fields.ts:33-src/workflows/ship/log-fields.ts:53 — existing ShipLogFieldsSchema with delta_ms / wall_clock_ms; pattern to mirror.
• src/workflows/ship/log-fields.ts:70 — SHIP_LOG_EVENTS typed event-key constant; same pattern for the new CORE_PIPELINE_LOG_EVENTS.
• docs/operate/observability.md:54 — documented delta_ms contract; needs a sibling "Core pipeline log fields" section after this lands.

External:

• Splunk - RED Metrics: Using Rate, Errors, and Duration — Tom Wilkie's RED method, the standard rationale for per-stage duration metrics on request-driven services.
• Better Stack - RED and USE Metrics for Monitoring and Observability — how RED applies to services like this webhook + worker pipeline and why per-step duration p50/p90/p99 is the right granularity.
• The New Stack - Monitoring Methodologies: RED and USE — canonical write-up of why stage-level duration matters for diagnosing slow requests.
• SigNoz - Pino Logger Guide — confirms process.hrtime.bigint() / Date.now() are the idiomatic ways to measure operation duration for structured-log timing in pino.
• Dash0 - Production-Grade Logging in Node.js with Pino — production guidance: include timing information on each log line so slow operations are queryable.
• pinojs/pino on GitHub — confirms the structured-payload approach (one JSON line per event with numeric fields, which downstream tools aggregate) used elsewhere in this repo is canonical.

Suggested Next Steps

1. Add a new src/core/log-fields.ts module mirroring src/workflows/ship/log-fields.ts: export CorePipelineLogFieldsSchema (Zod) with event, stage, delta_ms (per-event), pipeline_wall_clock_ms (cumulative), deliveryId, and a CORE_PIPELINE_LOG_EVENTS constant { started: "pipeline.started", stage: "pipeline.stage", completed: "pipeline.completed", failed: "pipeline.failed" }. Use the same .strict() Zod shape so unknown fields fail validation.
2. Instrument src/core/pipeline.ts: capture const pipelineStartedAt = Date.now() at the top of runPipeline. Wrap each stage boundary with a const t = Date.now(); … ; log.info({ event: "pipeline.stage", stage: "<name>", delta_ms: Date.now() - t }, "Pipeline stage completed"). Stages: trackingComment.create, token.resolve, github.fetch, prompt.build, repo.clone, executor.invoke, trackingComment.finalize, daemonActions.read, artifacts.read, workspace.cleanup.
3. Enrich the terminal success log at src/core/pipeline.ts:471 with pipeline_wall_clock_ms: Date.now() - pipelineStartedAt and event: "pipeline.completed". Mirror on the failure path at src/core/pipeline.ts:541 with event: "pipeline.failed". Keep the human-readable "Request processing completed/failed" msg so existing log queries still match.
4. Add cloneDurationMs to the Repository checked out and git configured log at src/core/checkout.ts:97 (capture const cloneStarted = Date.now() immediately before line 60). Same for fetchDurationMs at src/core/fetcher.ts:487. These nested timings are redundant with the pipeline-level stage events but make per-file log queries self-contained.
5. Update docs/operate/observability.md "Common log fields" with stage, delta_ms, and pipeline_wall_clock_ms; add a "Core pipeline log fields" section parallel to "Ship workflow log fields" enumerating the four event keys. CI-enforced citation gates in scripts/check-docs-citations.ts will keep the line numbers honest.
6. Optionally add a co-located test src/core/log-fields.test.ts that round-trips a representative pipeline.stage line through CorePipelineLogFieldsSchema, asserting that unknown / mistyped fields are rejected; matches the documented pattern from CLAUDE.md "Ship workflow log fields" subsection.

Areas Evaluated

• src/core/pipeline.ts end-to-end: runPipeline entry/exit, success log at :471, failure log at :541, dry-run path at :367.
• src/core/executor.ts: confirmed the only stage with a measured durationMs via startTime = Date.now() at :230 and the rich completion log at :436-:447.
• src/core/checkout.ts, src/core/fetcher.ts, src/core/tracking-comment.ts: confirmed each emits completion-level info logs without a duration field.
• src/daemon/job-executor.ts: outer-job durationMs from Date.now() - job.startedAt at :402 and :426; single bag, no per-stage breakdown sent over the WS job:result envelope.
• src/workflows/ship/log-fields.ts: existing Zod schema (ShipLogFieldsSchema, SHIP_LOG_EVENTS) the proposal mirrors; verified delta_ms / wall_clock_ms field names and the usdToCents helper convention.
• docs/operate/observability.md "Common log fields" and "Ship workflow log fields" sections (around lines 17-72).
• Searched for existing per-stage timing (grep performance.now|hrtime|durationMs|startedAt|Date.now) across src/; only the agent executor and the daemon job-executor outer band measure durations on the dispatch hot path.

---

Generated by the scheduled research action on 2026-05-22

[chrisleekr]

Starting + implemented.

Validation (HEAD)

Confirmed: in runPipeline only the agent invocation is timed (executor.ts durationMs); tracking-comment create, token resolve, GraphQL fetch, clone, finalize, cleanup all log completion without a duration, and the pipeline has no own wall-clock. Valid.

Implementation

• New src/core/log-fields.ts mirroring src/workflows/ship/log-fields.ts: CORE_PIPELINE_LOG_EVENTS (started/stage/completed/failed), a .strict() PipelineStageLogSchema, and logPipelineStage / timeStage helpers.
• Instrumented runPipeline: pipeline.started at entry; timeStage(...) wraps the awaited stages (trackingComment.create, token.resolve, github.fetch, repo.clone, executor.invoke, trackingComment.finalize, workspace.cleanup), each emitting pipeline.stage with delta_ms; prompt.build bracketed inline. Terminal success/failure logs enriched with event + pipeline_wall_clock_ms (cumulative), human-readable msg preserved so existing queries still match.
• test/core/log-fields.test.ts round-trips the strict schema (accept valid, reject unknown field / non-int / negative / wrong event).
• Docs: observability.md gets the three new field rows + a "Core pipeline log fields" section.

Judgement call (scope)

Skipped the proposed redundant nested timings (cloneDurationMs in checkout.ts, fetchDurationMs in fetcher.ts): the proposal itself calls them "redundant with the pipeline-level stage events," and repo.clone / github.fetch stage events already capture those durations. Avoiding them keeps the change surgical (no edits to checkout.ts / fetcher.ts). pipeline.started is emitted; the tiny post-execution file reads (daemonActions / artifacts) are left uninstrumented (sub-ms reads, negligible).

timeStage only emits the stage event on success, so a throwing stage does not log a misleading "completed" timing; the failure is captured by the pipeline.failed terminal line.

Verification

typecheck / eslint (0 errors) / prettier / em-dash / docs-citations clean. test/core/log-fields.test.ts 5 pass. No regression: the 3 pre-existing fetcher.ts pagination failures are identical on clean main (verified by stash); my change adds only passing tests.