feat(telemetry): first-run health — startup_ready, event_loop_stall, registration timing

Merged
AN
2mo ago
+557-10

Why

The 0.11.0 first-run freeze (#1292: an in-process @npmcli/arborist install blocking Bun's event loop for 2.5 to 5 minutes) shipped in six releases without a trace in telemetry. Three reasons, all structural:

  1. Nothing timed startup or registration. The first event a session reports is session_start; the next is a generation after the model answers. A freeze between them produced no number anywhere.
  2. Events flush on a 5 s setInterval on the same loop that was blocked. A frozen-then-killed process died with its buffer and left only session_start + task_classified (a "dead session": 0 to 2 s span, no generation, no error, no end).
  3. The only place it was visible was first-generation latency split by brand-new versus returning machines, which no default view does. Fresh machines on 0.9.5 and 0.9.7 had a p90 of 195 to 244 s versus 17 to 21 s for returning ones.

What

EventEmittedFields
startup_readyonce per process: serve listening, TUI transport resolved, run about to send its first promptcommand, duration_ms (process uptime), fresh_install
event_loop_stalla 250 ms monitor tick that fires more than 1 s late; capped at 20 per process; main thread and TUI server workerblocked_ms, since_start_ms, thread, command
altimate_base_registrationevery registerAfterConsent outcome, so the TUI dialog and the HTTP consent route both countresult, duration_ms, status

Plus: anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting for the interval, and the CLI middleware records the top-level command via Telemetry.setCommand.

The stall monitor reports when the loop resumes, so a stall that ends in a killed process is still lost, but every stall a user waited through is now a number, and it is flushed before anything else can go wrong.

docs/internal/first-run-telemetry.md carries the rationale, the event table, and KQL for startup time, stalls, registration, and the fresh-versus-returning dead-session rate (the last one works on historical data).

Verification

  • bun test: 8 new tests (startup_ready once per process; pure lag check; monitor detects a synchronous 250 ms block and stays quiet otherwise; idempotent start/stop; registration success, HTTP 429 with status, misconfigured gateway URL, network failure) plus the existing telemetry, Altimate Base, TUI and provider-API suites, all green. tsgo --noEmit clean. Upstream marker guard clean.
  • Live: serve in a fresh isolated HOME with APPLICATIONINSIGHTS_CONNECTION_STRING pointed at a local sink received startup_ready command=serve within the anchor flush, from both the dev build (2048 ms) and a bun build --compile single-target binary (1561 ms), so the monitor and isMainThread behave in the compiled form.
  • Second-model review folded in: startup_ready now fires for run --command as well as plain prompts, and a ConfigurationError from the gateway URL is reported as result: configuration instead of escaping before the timer starts.

Known limit

Telemetry is initialised and shut down per prompt by session/prompt.ts, so in a long-lived serve process the stall monitor, like every other event, is dark between prompts. That is pre-existing lifecycle behaviour, noted here so nobody reads an absence of stalls outside a prompt window as proof of health.

🤖 Generated with Claude Code

https://claude.ai/code/session_01WrT7MEUL5CYvpjf9cJbeQR


[!NOTE]
Medium Risk
Touches telemetry flush timing and runs instrumentation on CLI main thread and TUI worker at startup; low user-facing risk but changes when events ship and adds process-lifetime monitors tied to telemetry init/shutdown.

Overview
Adds first-run health telemetry so long startup freezes and silent “dead sessions” show up in App Insights instead of only session_start with no follow-up.

New events: startup_ready (once per process when tui / serve / run can work, with uptime and fresh_install), event_loop_stall (250 ms monitor, >1 s late tick, capped at 20, main vs worker), and altimate_base_registration (every registerAfterConsent outcome with duration and HTTP status when relevant).

Behavior: Selected anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting on the 5 s interval. CLI middleware records the top-level command via Telemetry.setCommand; the TUI worker starts the stall monitor and calls Telemetry.init() at boot so pre-prompt blocking is observable.

Altimate Base: Registration paths report telemetry for expired consent, bad gateway URL (configuration), success/failure; caller aborts are classified as cancelled rather than network.

Docs/tests: docs/internal/first-run-telemetry.md with KQL for startup, stalls, registration, and dead-session rate; new unit tests plus an existing flush-retry test adjusted to avoid anchor auto-flush.

Reviewed by Cursor Bugbot for commit f6343e2085e259f27014da0990a93f74df51cdbe. Bugbot is set up for automated code reviews on this repo. Configure here.


Summary by cubic

Adds first-run health telemetry so the 2.5–5 minute freeze from the 0.11.0 first-run @npmcli/arborist install shows up in telemetry instead of a "dead session" that reports only session_start.

  • Emits startup_ready once per process when serve, tui, or run can start work, with command, duration, and fresh-install flag.
  • Emits event_loop_stall when a 250 ms monitor tick is over 1 s late, capped at 20 per process, on main and worker threads; the TUI worker starts the monitor at boot.
  • Emits altimate_base_registration for every registration outcome on both TUI and HTTP consent paths; a caller abort reports cancelled and a bad gateway URL reports configuration.
  • Anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting for the 5 s interval.
  • CLI middleware records the top-level command via Telemetry.setCommand, and documentation with KQL queries lives in docs/internal/first-run-telemetry.md.

Summary by CodeRabbit

  • New Features

    • Added first-run health telemetry for startup readiness and event-loop stalls across CLI, server, and TUI workflows.
    • Added telemetry for Altimate Base registration outcomes, including duration, result type, cancellation status, and relevant HTTP status details.
    • Startup health events now flush immediately for more timely reporting.
  • Documentation

    • Added guidance for interpreting first-run health telemetry and querying startup, event-loop, registration, and session metrics.