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

docs/internal/first-run-telemetry.md

@@ -0,0 +1,79 @@
+# First-run health telemetry
+
+CLI telemetry lands in Azure Application Insights (`altimate-code-os`). Event names are the
+`Telemetry.Event` `type`; string properties are in `customDimensions`, numbers in
+`customMeasurements`, and `session_id` is lifted into the `session_Id` column.
+
+## Why these events exist
+
+On 2026-09-09 a fresh 0.11.0 install froze for 2.5 to 5 minutes on first use (an in-process
+`@npmcli/arborist` install blocked Bun's event loop). Nothing in telemetry showed it:
+
+- no event timed startup or registration, so a silent freeze produced no number anywhere;
+- events flush on a 5 s interval on the same loop, so a frozen-then-killed process died with
+  its buffer and left only `session_start` + `task_classified` (a "dead session");
+- the only place it was visible was first-generation latency split by brand-new versus
+  returning machines, which no default view does.
+
+Three events and one behaviour change close the gap:
+
+| Event | Emitted | Key fields |
+|---|---|---|
+| `startup_ready` | once per process when `tui`, `serve` or `run` can do work | `command`, `duration_ms` (process uptime), `fresh_install` |
+| `event_loop_stall` | when a 250 ms monitor tick fires more than 1 s late, capped at 20 per process | `blocked_ms`, `since_start_ms`, `thread`, `command` |
+| `altimate_base_registration` | on every `registerAfterConsent` outcome (TUI and HTTP consent paths) | `result`, `duration_ms`, `status` |
+
+Anchor events (`first_launch`, `startup_ready`, `event_loop_stall`, `altimate_base_registration`,
+`session_start`) flush immediately instead of waiting for the interval.
+
+## Queries (KQL)
+
+Startup time by command, fresh versus returning machines:
+
+```kusto
+customEvents
+| where timestamp > ago(7d) and name == "startup_ready"
+| extend v=tostring(customDimensions.cli_version), cmd=tostring(customDimensions.command), fresh=tostring(customDimensions.fresh_install)
+| summarize n=count(), p50_s=percentile(todouble(customMeasurements.duration_ms)/1000,50), p90_s=percentile(todouble(customMeasurements.duration_ms)/1000,90) by v, cmd, fresh
+| order by v desc
+```
+
+Event-loop stalls (the freeze, measured directly):
+
+```kusto
+customEvents
+| where timestamp > ago(7d) and name == "event_loop_stall"
+| extend v=tostring(customDimensions.cli_version), cmd=tostring(customDimensions.command), thread=tostring(customDimensions.thread)
+| summarize stalls=count(), machines=dcount(user_Id), p50_blocked_s=percentile(todouble(customMeasurements.blocked_ms)/1000,50), max_blocked_s=max(todouble(customMeasurements.blocked_ms))/1000 by v, cmd, thread
+| order by machines desc
+```
+
+Registration outcome and latency:
+
+```kusto
+customEvents
+| where timestamp > ago(7d) and name == "altimate_base_registration"
+| extend v=tostring(customDimensions.cli_version), result=tostring(customDimensions.result)
+| summarize n=count(), p50_s=percentile(todouble(customMeasurements.duration_ms)/1000,50), p90_s=percentile(todouble(customMeasurements.duration_ms)/1000,90) by v, result
+```
+
+Dead-session rate, fresh versus returning (works on historical data too):
+
+```kusto
+let fresh = customEvents
+| where timestamp > ago(30d) and name == "first_launch" and tostring(customDimensions.is_upgrade) == "false"
+| summarize launch=min(timestamp) by user_Id;
+customEvents
+| where timestamp > ago(30d) and isnotempty(session_Id)
+| extend v=tostring(customDimensions.cli_version)
+| summarize started=countif(name=="session_start"), gens=countif(name=="generation"), errors=countif(name in ("error","provider_error")), start=minif(timestamp, name=="session_start"), last_ts=max(timestamp), ver=any(v) by session_Id, user_Id
+| where started > 0
+| join kind=leftouter fresh on user_Id
+| extend fresh_machine = isnotnull(launch) and start between (launch .. (launch + 24h))
+| extend dead = gens == 0 and errors == 0 and datetime_diff("second", last_ts, start) <= 2
+| summarize sessions=count(), dead_pct=round(100.0*countif(dead)/count(),1), generated_pct=round(100.0*countif(gens > 0)/count(),1) by ver, fresh_machine
+| order by ver desc, fresh_machine desc
+```
+
+Gotchas: the `az monitor app-insights query --analytics-query` argument must be a single line;
+`last` is a reserved word; `percentileif` does not exist (filter first, then `percentile`).

packages/opencode/src/altimate/free/client.ts

@@ -5,6 +5,8 @@ import { Installation } from "../../installation"
 import { Log } from "../util/log"
 import { FreeTierStore } from "./store"
 import { FreeTierUrl } from "./url"
+// altimate_change — first-run health: time every Altimate Base registration
+import { Telemetry } from "../telemetry"
 
 const log = Log.create({ service: "altimate-base" })
 
@@ -285,6 +287,12 @@ async function registerOnce(
         : AbortSignal.timeout(REGISTER_TIMEOUT_MS),
     })
   } catch (error) {
+    // altimate_change start — first-run health: a caller abort is a cancellation, not a gateway
+    // failure; keep the registration timeout classified as network.
+    if (signal?.aborted) {
+      throw new RegistrationError("Altimate Base registration was cancelled.", "cancelled")
+    }
+    // altimate_change end
     log.warn("Altimate Base registration request failed", { error })
     throw new RegistrationError("Could not reach the Altimate Base gateway. Check your connection.", "network")
   }
@@ -360,10 +368,22 @@ export async function registerAfterConsent(
   token: string,
   input: { signal?: AbortSignal } = {},
 ): Promise<Credentials> {
+  // altimate_change start — first-run health: every outcome is a registration outcome, including an
+  // expired consent token and a misconfigured gateway URL
+  const startedAt = performance.now()
   if (!redeemConsent(token)) {
-    throw new RegistrationError("Altimate Base consent expired. Reopen setup and try again.", "cancelled")
+    const expired = new RegistrationError("Altimate Base consent expired. Reopen setup and try again.", "cancelled")
+    reportRegistration("cancelled", startedAt, expired)
+    throw expired
+  }
+  let configuredGateway: string
+  try {
+    configuredGateway = gatewayUrl()
+  } catch (error) {
+    reportRegistration(registrationResult(error), startedAt, error)
+    throw error
   }
-  const configuredGateway = gatewayUrl()
+  // altimate_change end
   const dedupeKey = configuredGateway
   const pending = inflight.get(dedupeKey)
   if (pending) return pending
@@ -408,9 +428,48 @@ export async function registerAfterConsent(
     if (inflight.get(dedupeKey) === started) inflight.delete(dedupeKey)
   })
   inflight.set(dedupeKey, started)
+  // altimate_change start — report the outcome on a side branch so the caller's promise, and the
+  // dedupe bookkeeping above, are untouched; the rejection handler keeps the branch from surfacing
+  // as an unhandled rejection.
+  started.then(
+    () => reportRegistration("success", startedAt),
+    (error: unknown) => reportRegistration(registrationResult(error), startedAt, error),
+  )
+  // altimate_change end
   return started
 }
 
+// altimate_change start — first-run health: altimate_base_registration
+type RegistrationResult = Extract<Telemetry.Event, { type: "altimate_base_registration" }>["result"]
+
+function registrationResult(error: unknown): RegistrationResult {
+  if (error instanceof RegistrationError) return error.kind
+  if (error instanceof ConfigurationError) return "configuration"
+  // `signal.throwIfAborted()` before the request raises a DOMException named AbortError.
+  if (error instanceof Error && error.name === "AbortError") return "cancelled"
+  return "error"
+}
+
+function reportRegistration(result: RegistrationResult, startedAt: number, error?: unknown) {
+  const status = error instanceof RegistrationError ? error.status : undefined
+  const event: Telemetry.Event = {
+    type: "altimate_base_registration",
+    timestamp: Date.now(),
+    session_id: Telemetry.getContext().sessionId,
+    result,
+    duration_ms: Math.round(performance.now() - startedAt),
+    ...(status !== undefined ? { status } : {}),
+  }
+  // Registration can run before any prompt has initialised telemetry (TUI worker, serve after a
+  // session shutdown). init() is idempotent; tracking after it guarantees the anchor flush fires
+  // instead of the event sitting in a pre-init buffer that a killed process would lose.
+  void Telemetry.init().then(
+    () => Telemetry.track(event),
+    () => Telemetry.track(event),
+  )
+}
+// altimate_change end
+
 function targetUrl(input: RequestInfo | URL): string {
   return typeof input === "string" ? input : input instanceof URL ? input.href : input.url
 }

packages/opencode/src/altimate/telemetry/index.ts

@@ -6,6 +6,8 @@ import { Log } from "@/altimate/util/log"
 // altimate_change — shared machine-id helper (race-safe, UUID-validated, size-capped)
 import { getOrCreateMachineId } from "@/altimate/util/machine-id"
 import { createHash, randomUUID } from "crypto"
+// altimate_change — first-run health: the event-loop stall monitor labels which thread stalled
+import { isMainThread } from "node:worker_threads"
 import fs from "fs"
 import path from "path"
 import os from "os"
@@ -652,6 +654,43 @@ export namespace Telemetry {
         install_method: "curl" | "powershell" | "npm" | "vscode-extension" | "local" | "unknown"
       }
     // altimate_change end
+    // altimate_change start — first-run health: startup readiness, event-loop stalls, registration timing.
+    // The 0.11.0 first-run freeze (an in-process @npmcli/arborist install blocking the loop for minutes)
+    // was invisible for two months: nothing timed startup or registration, and a blocked loop cannot
+    // flush, so a killed process left only `session_start`. These events close that gap.
+    | {
+        type: "startup_ready"
+        timestamp: number
+        session_id: string
+        /** Top-level CLI command, e.g. "tui", "serve", "run". */
+        command: string
+        /** Wall time from process start until the command could serve its first request or frame. */
+        duration_ms: number
+        /** True when this process emitted a non-upgrade first_launch, i.e. a brand-new machine. */
+        fresh_install: boolean
+      }
+    | {
+        type: "event_loop_stall"
+        timestamp: number
+        session_id: string
+        command: string
+        thread: "main" | "worker"
+        /** How long the event loop was blocked beyond the monitor's tick interval. */
+        blocked_ms: number
+        /** Process uptime when the loop resumed. */
+        since_start_ms: number
+      }
+    | {
+        type: "altimate_base_registration"
+        timestamp: number
+        session_id: string
+        /** RegistrationError.kind, "configuration" for a gateway URL problem, "error" otherwise. */
+        result: "success" | "network" | "http" | "response" | "cancelled" | "configuration" | "error"
+        duration_ms: number
+        /** HTTP status when result is "http". */
+        status?: number
+      }
+    // altimate_change end
     // altimate_change start — telemetry for skill management operations
     | {
         type: "skill_created"
@@ -2028,6 +2067,13 @@ export namespace Telemetry {
       const timer = setInterval(flush, FLUSH_INTERVAL_MS)
       if (typeof timer === "object" && timer && "unref" in timer) (timer as any).unref()
       flushTimer = timer
+      // altimate_change start — first-run health: watch for event-loop stalls wherever telemetry is
+      // live (CLI main thread and the TUI's server worker both init here), and drain anchor events
+      // that were tracked before init finished (first_launch always is) instead of leaving them to
+      // the 5 s interval a startup freeze would block.
+      startLoopMonitor()
+      if (buffer.some((event) => ANCHOR_EVENTS.has(event.type))) void Telemetry.flush().catch(() => {})
+      // altimate_change end
     } catch {
       buffer = []
     } finally {
@@ -2049,6 +2095,114 @@ export namespace Telemetry {
     return initDone && enabled
   }
 
+  // altimate_change start — first-run health instrumentation (see the startup_ready, event_loop_stall
+  // and altimate_base_registration taxonomy entries). Calls into `Telemetry.track`/`Telemetry.flush`
+  // below go through the namespace object on purpose so tests can observe them with spyOn.
+  const ANCHOR_EVENTS = new Set<Event["type"]>([
+    "first_launch",
+    "startup_ready",
+    "event_loop_stall",
+    "altimate_base_registration",
+    "session_start",
+  ])
+  const LOOP_MONITOR_INTERVAL_MS = 250
+  const LOOP_STALL_THRESHOLD_MS = 1_000
+  const LOOP_STALL_MAX_EVENTS = 20
+  // The TUI server worker loads its own copy of this module; the CLI middleware publishes the
+  // command through the environment so the worker's stall events carry it too.
+  const COMMAND_ENV = "ALTIMATE_CLI_COMMAND"
+  let command = process.env[COMMAND_ENV] ?? "unknown"
+  let freshInstall = false
+  let startupReported = false
+  let loopTimer: ReturnType<typeof setInterval> | undefined
+  let loopExpectedAt = 0
+  let loopStallsEmitted = 0
+
+  /** Top-level CLI command name, recorded once by the CLI middleware. */
+  export function setCommand(name: string) {
+    command = name
+    process.env[COMMAND_ENV] = name
+  }
+
+  export function getCommand() {
+    return command
+  }
+
+  /** Emit startup_ready once per process; later calls are no-ops so per-message paths may call it. */
+  export function startupReady(name?: string) {
+    if (startupReported) return
+    startupReported = true
+    if (name) command = name
+    Telemetry.track({
+      type: "startup_ready",
+      timestamp: Date.now(),
+      session_id: sessionId,
+      command,
+      duration_ms: Math.round(performance.now()),
+      fresh_install: freshInstall,
+    })
+  }
+
+  /** Pure lag check, exported for tests: the stall event when a tick is late by more than the threshold. */
+  export function loopStallFor(
+    now: number,
+    expectedAt: number,
+    thresholdMs: number,
+    thread: "main" | "worker",
+  ): Event | undefined {
+    const lag = now - expectedAt
+    if (lag <= thresholdMs) return undefined
+    return {
+      type: "event_loop_stall",
+      timestamp: Date.now(),
+      session_id: sessionId,
+      command,
+      thread,
+      blocked_ms: Math.round(lag),
+      since_start_ms: Math.round(now),
+    }
+  }
+
+  /**
+   * Detect event-loop stalls: a timer that fires late by more than the threshold means the loop was
+   * blocked for that long. The event is recorded when the loop resumes, so a stall that ends in a
+   * killed process is still lost — but every stall the user waited through is now reported, and
+   * `track` flushes it immediately as an anchor event.
+   */
+  export function startLoopMonitor(opts: { intervalMs?: number; thresholdMs?: number } = {}) {
+    if (loopTimer) return
+    const interval = opts.intervalMs ?? LOOP_MONITOR_INTERVAL_MS
+    const threshold = opts.thresholdMs ?? LOOP_STALL_THRESHOLD_MS
+    const thread: "main" | "worker" = isMainThread ? "main" : "worker"
+    loopExpectedAt = performance.now() + interval
+    const timer = setInterval(() => {
+      const now = performance.now()
+      const stall = loopStallFor(now, loopExpectedAt, threshold, thread)
+      loopExpectedAt = now + interval
+      if (!stall || loopStallsEmitted >= LOOP_STALL_MAX_EVENTS) return
+      loopStallsEmitted++
+      Telemetry.track(stall)
+    }, interval)
+    if (typeof timer === "object" && timer && "unref" in timer) (timer as any).unref()
+    loopTimer = timer
+  }
+
+  export function stopLoopMonitor() {
+    if (loopTimer) clearInterval(loopTimer)
+    loopTimer = undefined
+  }
+
+  /** Test seam: the first-run latches are process-lifetime state and would otherwise leak across suites. */
+  export function resetFirstRunStateForTest() {
+    stopLoopMonitor()
+    command = process.env[COMMAND_ENV] ?? "unknown"
+    freshInstall = false
+    startupReported = false
+    loopStallsEmitted = 0
+    loopExpectedAt = 0
+  }
+  // altimate_change end
+
   export function track(event: Event) {
     // Before init completes: buffer (flushed once init enables, or cleared if disabled).
     // After init completed and disabled telemetry: drop silently.
@@ -2058,6 +2212,12 @@ export namespace Telemetry {
       buffer.shift()
       droppedEvents++
     }
+    // altimate_change start — anchor events flush immediately. A frozen-then-killed process otherwise
+    // dies with its buffer: the 5 s interval cannot fire while the loop is blocked, and the stall
+    // report itself would be the first thing lost.
+    if (event.type === "first_launch" && !event.is_upgrade) freshInstall = true
+    if (initDone && enabled && ANCHOR_EVENTS.has(event.type)) void Telemetry.flush().catch(() => {})
+    // altimate_change end
   }
 
   // altimate_change — `timeoutMs` lets exit paths bound the flush from the INSIDE. Racing
@@ -2193,6 +2353,9 @@ export namespace Telemetry {
         // init failed — nothing to flush
       }
     }
+    // altimate_change — first-run health: stop the stall monitor only once init has settled, so a
+    // shutdown that overlaps init cannot be undone by doInit() starting the monitor afterwards.
+    stopLoopMonitor()
     if (flushTimer) {
       clearInterval(flushTimer)
       flushTimer = undefined