feat(quorum): record which config produced each timeout window (I5)

CHANGELOG.md

@@ -26,6 +26,9 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/).
 
 ## [Unreleased]
 
+### Added
+- feat(quorum): **timeout records now say which config produced the window (I5).** `resolveTtfbTimeout` / `resolveInterChunkCeiling` each compute a `source` (`per-slot` / `default` / `idle-budget` / `legacy-stall`) and `recordTelemetry` was dropping both it and the resolved values, so a TIMEOUT in `quorum-rounds-*.jsonl` could be seen but never attributed — the number alone never answers "did *my* config do this?", since today's per-slot value can be tomorrow's default. Records now carry `ttfb_timeout_ms`, `ttfb_source`, `inter_chunk_ceiling_ms` and `inter_chunk_source`, always present (null when unknown) so the schema stays stable for analysis. Passed as a trailing options object rather than a 15th positional parameter. 4 tests drive the **real child** and read the actual log, so the fields are proven to survive the whole dispatch path; mutation-proven. Accepted as improvement I5 by the 2026-08-07 quorum.
+
 ### Fixed
 - fix(install): **a stale backup no longer clobbers live slot config on every install.** When `bin/providers.json` ships empty (it always does), install reconstructs the user's `providers.json` from `~/.claude.json` and overlays what it can recover for each slot, gathering from four candidates documented as being "in order of freshness" — live `nf-bin/` first, then two `nf-local-patches/` backups, then the legacy live path. The gather loop called `map.set(name, entry)` unconditionally, so the **last** candidate won: the exact inversion of the stated order. On the machine that surfaced it, a `nf-local-patches/nf/bin/providers.json` dated **2026-05-13** overrode the live entry for 7 slots on every single install, silently reverting per-slot tuning (`ttfb_timeout_ms`, `inter_chunk_ceiling_ms`, `idle_timeout_ms`, `model`, `env`). It was found because freshly-set `ttfb_timeout_ms` values kept vanishing after `install.js --claude --global`, which also explains earlier "mystery" resets of `stall_timeout_ms`. First writer now wins, so backups do what they exist for — recovering slots the live file has **lost** — and never override it. 4 tests in `bin/install-providers-precedence.test.cjs` execute the extracted gather loop against stubbed candidates; mutation-proven, and verified against a real install that now preserves every tuned field.
 

bin/call-quorum-slot.cjs

@@ -99,7 +99,7 @@ function appendTokenSentinel(slotName) {
 }
 
 // ─── Telemetry logging for quorum slot dispatch (OBS-01) ─────────────────────
-function recordTelemetry(slotName, round, verdict, latencyMs, provider, providerStatus, retryCount, errorType, truncated, truncationLayer, originalSizeBytes, outputPreview, outputLength, exitCode) {
+function recordTelemetry(slotName, round, verdict, latencyMs, provider, providerStatus, retryCount, errorType, truncated, truncationLayer, originalSizeBytes, outputPreview, outputLength, exitCode, timing) {
   try {
     const sessionId = process.env.CLAUDE_SESSION_ID || 'session-' + Date.now();
     const record = JSON.stringify({
@@ -119,6 +119,15 @@ function recordTelemetry(slotName, round, verdict, latencyMs, provider, provider
       output_preview: outputPreview || null,
       output_length: outputLength || null,
       exit_code: exitCode != null ? exitCode : null,
+      // STALL-TIMEOUT-03 observability: resolveTtfbTimeout/resolveInterChunkCeiling
+      // already compute a `source` for each window, and it was being dropped on the
+      // floor — so a timeout in the record could not be attributed to the config that
+      // caused it. Emitted unconditionally (null when unknown) to keep the schema
+      // stable for downstream analysis.
+      ttfb_timeout_ms: (timing && timing.ttfbMs) != null ? timing.ttfbMs : null,
+      ttfb_source: (timing && timing.ttfbSource) || null,
+      inter_chunk_ceiling_ms: (timing && timing.interChunkMs) != null ? timing.interChunkMs : null,
+      inter_chunk_source: (timing && timing.interChunkSource) || null,
     });
     const pp = require('./planning-paths.cjs');
     const logPath = pp.resolve(findProjectRoot(spawnCwd), 'quorum-rounds', { sessionId });
@@ -1126,6 +1135,7 @@ async function main() {
     process.stderr.write(`[call-quorum-slot] inter-chunk ceiling ${chunk.ms}ms capped to ${boundedChunk}ms by the hard/latency budget for slot ${slot}\n`);
   }
   const timers = { ttfb: Math.min(ttfb.ms, effectiveHardTimeout), interChunk: boundedChunk };
+  const timingMeta = { ttfbMs: timers.ttfb, ttfbSource: ttfb.source, interChunkMs: boundedChunk, interChunkSource: chunk.source };
 
   process.stderr.write(`[call-quorum-slot] Timeouts: idle=${effectiveIdleTimeout}ms hard=${effectiveHardTimeout}ms ttfb=${ttfb.ms}ms (${ttfb.source}) inter-chunk=${boundedChunk}ms (${chunk.source}) for slot ${slot}\n`);
 
@@ -1158,7 +1168,7 @@ async function main() {
       setScoreboardCooldown(slot, 'Unknown provider type: ' + provider.type);
       appendTokenSentinel(slot);
       const latencyMs = Date.now() - startMs;
-      recordTelemetry(slot, roundNum, 'FLAG', latencyMs, provider.provider || provider.name, 'unavailable', 0, 'UNKNOWN_TYPE', false, null, null, null, 0, null);
+      recordTelemetry(slot, roundNum, 'FLAG', latencyMs, provider.provider || provider.name, 'unavailable', 0, 'UNKNOWN_TYPE', false, null, null, null, 0, null, timingMeta);
       process.exit(1);
     }
 
@@ -1181,7 +1191,7 @@ async function main() {
         const verdict = parseVerdictLine(result) || 'UNKNOWN';
         const l1Detect = result.includes('[OUTPUT TRUNCATED at 10MB');
         process.stderr.write('[call-quorum-slot] WARNING: ' + slot + ' CLI exited non-zero (code ' + cliExitCode + ') but produced valid output -- treating as available\n');
-        recordTelemetry(slot, roundNum, verdict, latencyMs, providerName, 'available_with_warning', retryCount, null, l1Detect, l1Detect ? 'L1' : null, null, result.slice(0, 500), result.length, cliExitCode);
+        recordTelemetry(slot, roundNum, verdict, latencyMs, providerName, 'available_with_warning', retryCount, null, l1Detect, l1Detect ? 'L1' : null, null, result.slice(0, 500), result.length, cliExitCode, timingMeta);
         clearFailureOnSuccess(slot);
         writeInnerOutputFile(result);
         process.stdout.write(result);
@@ -1194,7 +1204,7 @@ async function main() {
       const latencyMs = Date.now() - startMs;
       const providerName = provider.provider || provider.name;
       const errorType = classifyErrorType(result);
-      recordTelemetry(slot, roundNum, 'FLAG', latencyMs, providerName, 'unavailable', retryCount, errorType, false, null, null, result.slice(0, 500), result.length, cliExitCode);
+      recordTelemetry(slot, roundNum, 'FLAG', latencyMs, providerName, 'unavailable', retryCount, errorType, false, null, null, result.slice(0, 500), result.length, cliExitCode, timingMeta);
       writeFailureLog(slot, result, '');
       setScoreboardCooldown(slot, result);
       // Still output the result so quorum-slot-dispatch can parse it
@@ -1210,7 +1220,7 @@ async function main() {
     const providerName = provider.provider || provider.name;
 
     const l1Detect = result.includes('[OUTPUT TRUNCATED at 10MB');
-    recordTelemetry(slot, roundNum, verdict, latencyMs, providerName, 'available', retryCount, null, l1Detect, l1Detect ? 'L1' : null, null, result.slice(0, 500), result.length, 0);
+    recordTelemetry(slot, roundNum, verdict, latencyMs, providerName, 'available', retryCount, null, l1Detect, l1Detect ? 'L1' : null, null, result.slice(0, 500), result.length, 0, timingMeta);
 
     // Slot succeeded — clear any failure records so next quorum run doesn't skip it
     clearFailureOnSuccess(slot);
@@ -1247,7 +1257,7 @@ async function main() {
 
     const errorType = classifyErrorType(err.message);
 
-    recordTelemetry(slot, roundNum, 'FLAG', latencyMs, providerName, 'unavailable', 0, errorType, false, null, null, err.message.slice(0, 500), 0, null);
+    recordTelemetry(slot, roundNum, 'FLAG', latencyMs, providerName, 'unavailable', 0, errorType, false, null, null, err.message.slice(0, 500), 0, null, timingMeta);
 
     process.stderr.write(`[call-quorum-slot] ${err.message}\n`);
     writeFailureLog(slot, err.message, '');

bin/telemetry-window-source.test.cjs

@@ -0,0 +1,96 @@
+#!/usr/bin/env node
+'use strict';
+// bin/telemetry-window-source.test.cjs
+//
+// STALL-TIMEOUT-03 resolves two windows and computes a `source` for each
+// (per-slot / default / idle-budget / legacy-stall). recordTelemetry dropped both on
+// the floor, so a TIMEOUT in the quorum-rounds log could not be attributed to the
+// config that produced it — you could see that a slot died, never why its window was
+// what it was. Accepted as improvement I5 by the 2026-08-07 quorum.
+
+const { test } = require('node:test');
+const assert = require('node:assert');
+const fs = require('node:fs');
+const os = require('node:os');
+const path = require('node:path');
+const { spawnSync } = require('node:child_process');
+
+const TMP = [];
+process.on('exit', () => { for (const d of TMP) { try { fs.rmSync(d, { recursive: true, force: true }); } catch (_) {} } });
+
+// Drive the REAL child so the fields are proven to survive the whole dispatch path,
+// not just the function that formats them.
+function dispatchAndReadTelemetry(providerExtras) {
+  const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'nf-telem-'));
+  TMP.push(dir);
+  fs.mkdirSync(path.join(dir, '.planning'), { recursive: true });
+  const cli = path.join(dir, 'fake-cli.cjs');
+  fs.writeFileSync(cli, "'use strict';\nprocess.stdout.write('verdict: APPROVE\\n');\n", 'utf8');
+  const providersPath = path.join(dir, 'providers.json');
+  fs.writeFileSync(providersPath, JSON.stringify({ providers: [{
+    name: 'fake-slot', type: 'subprocess', mainTool: 'node', cli: 'node',
+    args_template: [cli, '{prompt}'], ...providerExtras,
+  }] }), 'utf8');
+
+  spawnSync(process.execPath, [
+    path.join(__dirname, 'call-quorum-slot.cjs'), '--slot', 'fake-slot', '--cwd', dir, '--round', '1',
+  ], { cwd: dir, input: 'q\n', encoding: 'utf8', timeout: 30000,
+       env: { ...process.env, UNIFIED_PROVIDERS_CONFIG: providersPath } });
+
+  // Only the quorum-rounds log. A dispatch also writes .planning/telemetry/token-usage.jsonl,
+  // whose records ALSO carry a `slot` field — reading both let a token-usage row win the
+  // "last record" race and the assertions failed against a record that never had these
+  // fields to begin with.
+  const found = [];
+  (function walk(d) {
+    for (const e of fs.readdirSync(d, { withFileTypes: true })) {
+      const full = path.join(d, e.name);
+      if (e.isDirectory()) walk(full);
+      else if (/quorum-rounds.*\.jsonl?$/.test(e.name)) found.push(full);
+    }
+  })(path.join(dir, '.planning'));
+
+  const records = [];
+  for (const f of found) {
+    for (const line of fs.readFileSync(f, 'utf8').split('\n')) {
+      if (!line.trim()) continue;
+      try { const r = JSON.parse(line); if (r.slot === 'fake-slot' && 'verdict' in r) records.push(r); } catch (_) {}
+    }
+  }
+  return records;
+}
+
+test('TWS-1: the record carries both windows AND the source of each', () => {
+  const recs = dispatchAndReadTelemetry({ idle_timeout_ms: 90000 });
+  assert.ok(recs.length > 0, 'the dispatch wrote no telemetry record for the slot');
+  const r = recs[recs.length - 1];
+  assert.strictEqual(r.ttfb_source, 'default', 'an unconfigured TTFB must be attributed to the default');
+  assert.strictEqual(r.ttfb_timeout_ms, 30000);
+  assert.strictEqual(r.inter_chunk_source, 'idle-budget');
+  assert.ok(r.inter_chunk_ceiling_ms > 0);
+});
+
+test('TWS-2: a per-slot window is attributed to the slot, not the default', () => {
+  // The distinction the field exists for: 150000 could be a default in some future
+  // build, so the number alone never answers "did MY config do this?".
+  const recs = dispatchAndReadTelemetry({ ttfb_timeout_ms: 150000, inter_chunk_ceiling_ms: 660000 });
+  const r = recs[recs.length - 1];
+  assert.strictEqual(r.ttfb_timeout_ms, 150000);
+  assert.strictEqual(r.ttfb_source, 'per-slot');
+  assert.strictEqual(r.inter_chunk_source, 'per-slot');
+});
+
+test('TWS-3: a legacy stall_timeout_ms is reported as legacy, not silently normalised', () => {
+  // Otherwise a config still on the old field looks identical to one that migrated.
+  const recs = dispatchAndReadTelemetry({ stall_timeout_ms: 270000 });
+  const r = recs[recs.length - 1];
+  assert.strictEqual(r.inter_chunk_source, 'legacy-stall');
+  assert.strictEqual(r.inter_chunk_ceiling_ms, 270000);
+});
+
+test('TWS-4: the fields are always present, so the schema is stable', () => {
+  const r = dispatchAndReadTelemetry({}).pop();
+  for (const k of ['ttfb_timeout_ms', 'ttfb_source', 'inter_chunk_ceiling_ms', 'inter_chunk_source']) {
+    assert.ok(Object.prototype.hasOwnProperty.call(r, k), `record is missing ${k}`);
+  }
+});