Milestone 5: observability - event log, usage ledger, trace (Tasks 22-24)

.kiro/specs/loop-engine/tasks.md

@@ -57,9 +57,9 @@ Each task references the requirement(s) it satisfies.
 
 ## Milestone 5 — Observability
 
-- [ ] 22. Structured event log for transitions and runner calls _(Req 11)_
-- [ ] 23. Usage/cost ledger per role and per run _(Req 11)_
-- [ ] 24. Session trace inspection _(Req 11)_
+- [~] 22. Structured event log for transitions and runner calls _(Req 11)_
+- [~] 23. Usage/cost ledger per role and per run _(Req 11)_
+- [~] 24. Session trace inspection _(Req 11)_
 
 ## Milestone 6 — Desktop delivery
 

package.json

@@ -10,6 +10,7 @@
   "scripts": {
     "demo": "tsx src/demo.ts",
     "start": "tsx src/run.ts",
+    "trace": "tsx src/trace.ts",
     "test": "vitest run",
     "test:watch": "vitest",
     "typecheck": "tsc --noEmit"

src/adapters/roleBindings.ts

@@ -4,6 +4,7 @@ import { createRunner, type RunnerFactory } from "../runners/runnerFactory.js";
 import type { Actor, Critic } from "./agents.js";
 import { RunnerActor, RunnerCritic } from "./runnerRoles.js";
 import type { ActorPromptTemplates, CriticPromptTemplates } from "./prompts.js";
+import { instrumentRunner, type RunnerCallSink } from "../observability/instrument.js";
 
 /**
  * Configuration -> roles wiring (Task 13.3).
@@ -35,6 +36,8 @@ export interface CreateRolesOptions {
   /** workspace the runners operate in (single dir until worktrees, Milestone 4) */
   cwd?: string;
   log?: (line: string) => void;
+  /** when set, every runner call emits an event attributed to its role (M5) */
+  onRunnerCall?: RunnerCallSink;
 }
 
 function resolveProfile(
@@ -80,13 +83,22 @@ export function createRoles(
   const actorProfile = resolveProfile(profiles, "actor", config.actorRunner, config.actorModel);
   const criticProfile = resolveProfile(profiles, "critic", config.criticRunner, config.criticModel);
 
-  const actor = new RunnerActor(factory(actorProfile), {
+  const actorRunner = factory(actorProfile);
+  const criticRunner = factory(criticProfile);
+  const instrumentedActor = opts.onRunnerCall
+    ? instrumentRunner(actorRunner, "actor", opts.onRunnerCall)
+    : actorRunner;
+  const instrumentedCritic = opts.onRunnerCall
+    ? instrumentRunner(criticRunner, "critic", opts.onRunnerCall)
+    : criticRunner;
+
+  const actor = new RunnerActor(instrumentedActor, {
     ...(opts.actorPrompts ? { prompts: opts.actorPrompts } : {}),
     ...(opts.cwd ? { cwd: opts.cwd } : {}),
     ...(opts.log ? { log: opts.log } : {}),
   });
 
-  const critic = new RunnerCritic(factory(criticProfile), {
+  const critic = new RunnerCritic(instrumentedCritic, {
     ...(opts.criticPrompts ? { prompts: opts.criticPrompts } : {}),
     ...(opts.cwd ? { cwd: opts.cwd } : {}),
     ...(opts.log ? { log: opts.log } : {}),

src/observability/events.ts

@@ -0,0 +1,69 @@
+/**
+ * Observability event shapes (Milestone 5).
+ *
+ * The store already persists transitions, attempts, and outcomes as typed
+ * tables; these are the *other* structured events a full trace needs — chiefly
+ * runner invocations (Req 11.1) — plus session lifecycle markers. They are
+ * written to the store's generic event stream (EventRecord) and read back for
+ * the usage ledger (Task 23) and trace view (Task 24).
+ */
+
+export type RoleName = "actor" | "critic";
+
+/** Token usage, normalized from a provider's (free-form) usage object. */
+export interface TokenUsage {
+  promptTokens: number;
+  completionTokens: number;
+  totalTokens: number;
+}
+
+export const ZERO_USAGE: TokenUsage = { promptTokens: 0, completionTokens: 0, totalTokens: 0 };
+
+/** One runner invocation, attributed to the role that made it. */
+export interface RunnerCallEvent {
+  role: RoleName;
+  runnerId: string;
+  model: string;
+  promptChars: number;
+  outputChars: number;
+  durationMs: number;
+  quotaExhausted: boolean;
+  usage: TokenUsage;
+  at: string;
+}
+
+export const EVENT_TYPES = {
+  sessionStarted: "session_started",
+  planReviewed: "plan_reviewed",
+  runnerCall: "runner_call",
+  sessionFinished: "session_finished",
+} as const;
+
+function num(v: unknown): number {
+  return typeof v === "number" && Number.isFinite(v) ? v : 0;
+}
+
+/**
+ * Normalizes a provider's usage object into {prompt,completion,total} tokens.
+ * Accepts the common OpenAI-style keys and the input/output variant; missing
+ * fields are zero, and a total is derived when absent.
+ */
+export function normalizeUsage(usage: unknown): TokenUsage {
+  if (usage === null || typeof usage !== "object") return { ...ZERO_USAGE };
+  const u = usage as Record<string, unknown>;
+  // Prefer the first key that is actually PRESENT, not the first truthy one:
+  // `||` would discard a legitimate 0 (e.g. an empty prompt) in favor of a
+  // later alias, corrupting the usage ledger.
+  const pick = (...keys: string[]): number => {
+    for (const k of keys) if (k in u) return num(u[k]);
+    return 0;
+  };
+  const prompt = pick("prompt_tokens", "input_tokens", "promptTokens");
+  const completion = pick("completion_tokens", "output_tokens", "completionTokens");
+  const totalRaw = pick("total_tokens", "totalTokens");
+  return {
+    promptTokens: prompt,
+    completionTokens: completion,
+    totalTokens: totalRaw || prompt + completion,
+  };
+}

src/observability/instrument.ts

@@ -0,0 +1,37 @@
+import type { AgentRunner, RunRequest, RunResult } from "../runners/agentRunner.js";
+import { normalizeUsage, type RoleName, type RunnerCallEvent } from "./events.js";
+
+export type RunnerCallSink = (e: RunnerCallEvent) => void | Promise<void>;
+
+/**
+ * Wraps a runner so every invocation emits a {@link RunnerCallEvent} attributed
+ * to its role (Task 22). The wrapper is transparent — it returns the underlying
+ * result unchanged — and times the call itself rather than trusting backend
+ * metadata, while still surfacing the provider's token `usage` for the ledger.
+ */
+export function instrumentRunner(
+  runner: AgentRunner,
+  role: RoleName,
+  onCall: RunnerCallSink,
+): AgentRunner {
+  return {
+    profile: runner.profile,
+    async run(req: RunRequest): Promise<RunResult> {
+      const started = Date.now();
+      const res = await runner.run(req);
+      const event: RunnerCallEvent = {
+        role,
+        runnerId: runner.profile.id,
+        model: runner.profile.model,
+        promptChars: req.prompt.length,
+        outputChars: res.text.length,
+        durationMs: Date.now() - started,
+        quotaExhausted: res.quotaExhausted ?? false,
+        usage: normalizeUsage(res.meta?.usage),
+        at: new Date().toISOString(),
+      };
+      await onCall(event);
+      return res;
+    },
+  };
+}

src/observability/trace.ts

@@ -0,0 +1,96 @@
+import type {
+  AttemptRecord,
+  EventRecord,
+  OutcomeRecord,
+  SessionRecord,
+  Store,
+  TaskRecord,
+  TransitionRecord,
+} from "../storage/store.js";
+import { computeUsage, runnerCalls, type Rates, type UsageLedger } from "./usage.js";
+
+/**
+ * Session trace inspection (Task 24): assembles a session's full, ordered story
+ * from the store — lifecycle, per-task state history, build attempts, runner
+ * calls, and outcomes — plus the computed usage ledger (Req 11.3). `formatTrace`
+ * renders it for a human; the structured `SessionTrace` is what a UI consumes.
+ */
+
+export interface SessionTrace {
+  session: SessionRecord | undefined;
+  tasks: TaskRecord[];
+  transitions: TransitionRecord[];
+  attempts: AttemptRecord[];
+  outcomes: OutcomeRecord[];
+  events: EventRecord[];
+  usage: UsageLedger;
+}
+
+export async function buildTrace(
+  store: Store,
+  sessionId: string,
+  rates: Rates = {},
+): Promise<SessionTrace> {
+  const [session, tasks, transitions, attempts, events] = await Promise.all([
+    store.getSession(sessionId),
+    store.listTasks(sessionId),
+    store.listTransitions(sessionId),
+    store.listAttempts(sessionId),
+    store.listEvents(sessionId),
+  ]);
+
+  const outcomes: OutcomeRecord[] = [];
+  for (const t of tasks) {
+    const o = await store.getOutcome(sessionId, t.taskId);
+    if (o) outcomes.push(o);
+  }
+
+  return {
+    session,
+    tasks,
+    transitions,
+    attempts,
+    outcomes,
+    events,
+    usage: computeUsage(runnerCalls(events), rates),
+  };
+}
+
+function money(n: number | undefined): string {
+  return n === undefined ? "" : ` $${n.toFixed(4)}`;
+}
+
+/** Renders a trace as readable text (CLI / logs). */
+export function formatTrace(trace: SessionTrace): string {
+  const lines: string[] = [];
+  const s = trace.session;
+  lines.push(`Session ${s?.id ?? "(unknown)"} — ${s?.status ?? "?"}`);
+  if (s) {
+    lines.push(`  goal: ${s.goal}`);
+    lines.push(`  plan: approved=${s.planApproved ?? "?"} revisions=${s.planRevisions ?? 0}`);
+  }
+
+  lines.push("\n  Tasks:");
+  for (const t of trace.tasks) {
+    const verified = t.verified ? " (verified)" : "";
+    lines.push(`    ${t.taskId.padEnd(12)} ${t.state}${verified}`);
+    const tx = trace.transitions.filter((x) => x.taskId === t.taskId);
+    for (const x of tx) lines.push(`        ${x.from} --(${x.event})--> ${x.to}  ${x.reason}`);
+  }
+
+  const u = trace.usage;
+  lines.push("\n  Usage:");
+  for (const role of ["actor", "critic"] as const) {
+    const r = u.perRole[role];
+    lines.push(
+      `    ${role.padEnd(7)} calls=${r.calls} tokens=${r.totalTokens} ` +
+        `(prompt ${r.promptTokens} / completion ${r.completionTokens}) ` +
+        `quotaHits=${r.quotaHits}${money(r.costUsd)}`,
+    );
+  }
+  lines.push(
+    `    ${"TOTAL".padEnd(7)} calls=${u.total.calls} tokens=${u.total.totalTokens}${money(u.total.costUsd)}`,
+  );
+
+  return lines.join("\n");
+}

src/observability/usage.ts

@@ -0,0 +1,81 @@
+import type { EventRecord } from "../storage/store.js";
+import { EVENT_TYPES, type RoleName, type RunnerCallEvent } from "./events.js";
+
+/**
+ * Usage/cost ledger (Task 23): aggregates runner-call events per role and for
+ * the run as a whole (Req 11.2). Cost is optional — supply per-1k-token rates
+ * to get a dollar estimate; otherwise the ledger is token/call/duration counts.
+ */
+
+export interface RoleUsage {
+  calls: number;
+  promptTokens: number;
+  completionTokens: number;
+  totalTokens: number;
+  durationMs: number;
+  /** number of calls that reported an exhausted quota */
+  quotaHits: number;
+  /** present only when rates were supplied */
+  costUsd?: number;
+}
+
+export interface UsageLedger {
+  perRole: Record<RoleName, RoleUsage>;
+  total: RoleUsage;
+}
+
+/** Per-role pricing in dollars per 1,000 tokens. */
+export type Rates = Partial<
+  Record<RoleName, { per1kPrompt?: number; per1kCompletion?: number }>
+>;
+
+function emptyRole(): RoleUsage {
+  return { calls: 0, promptTokens: 0, completionTokens: 0, totalTokens: 0, durationMs: 0, quotaHits: 0 };
+}
+
+function add(into: RoleUsage, e: RunnerCallEvent): void {
+  into.calls += 1;
+  into.promptTokens += e.usage.promptTokens;
+  into.completionTokens += e.usage.completionTokens;
+  into.totalTokens += e.usage.totalTokens;
+  into.durationMs += e.durationMs;
+  if (e.quotaExhausted) into.quotaHits += 1;
+}
+
+/** Pulls the runner-call events out of a session's generic event stream. */
+export function runnerCalls(events: EventRecord[]): RunnerCallEvent[] {
+  return events
+    .filter((e) => e.type === EVENT_TYPES.runnerCall)
+    .map((e) => e.data as unknown as RunnerCallEvent);
+}
+
+export function computeUsage(calls: RunnerCallEvent[], rates: Rates = {}): UsageLedger {
+  const perRole: Record<RoleName, RoleUsage> = { actor: emptyRole(), critic: emptyRole() };
+  for (const call of calls) {
+    add(perRole[call.role], call);
+  }
+
+  for (const role of ["actor", "critic"] as const) {
+    const rate = rates[role];
+    if (rate) {
+      const u = perRole[role];
+      u.costUsd =
+        (u.promptTokens / 1000) * (rate.per1kPrompt ?? 0) +
+        (u.completionTokens / 1000) * (rate.per1kCompletion ?? 0);
+    }
+  }
+
+  const total = emptyRole();
+  for (const role of ["actor", "critic"] as const) {
+    const u = perRole[role];
+    total.calls += u.calls;
+    total.promptTokens += u.promptTokens;
+    total.completionTokens += u.completionTokens;
+    total.totalTokens += u.totalTokens;
+    total.durationMs += u.durationMs;
+    total.quotaHits += u.quotaHits;
+    if (u.costUsd !== undefined) total.costUsd = (total.costUsd ?? 0) + u.costUsd;
+  }
+
+  return { perRole, total };
+}