nostr: dev-gated REQ tracer at the pool.sub choke point (#9)

The cold-login REQ storm's remaining emitters are unpinned (the suspected
per-contact list loops don't exist; mutes are already batched). Every
sub/list flows through the shimmed pool.sub, so recordReq() there aggregates
kinds + relay fan-out + emitting call site per 10s window. Zero-cost when
off; arm with localStorage bitvid:reqTrace=1 (auto in dev mode), read
[req-trace] logs or window.__bitvidReqTrace.report().

One traced cold login on unstable will name the storm's sources; the
batching/deferral pass follows from that data.

Tests: tests/req-telemetry.test.mjs (3).

Co-Authored-By: Claude Fable 5 <[email protected]>

js/nostr/reqTelemetry.js

@@ -0,0 +1,184 @@
+// js/nostr/reqTelemetry.js
+//
+// Dev-gated REQ tracer for TODO #9 (cold-login relay-REQ storm). Every
+// subscription that goes through the shimmed pool.sub/pool.list choke point is
+// recorded — kinds, relay fan-out, and the first call site outside the nostr
+// plumbing — so one traced cold login tells us exactly WHICH code paths emit
+// the burst (the storm's remaining sources are unpinned; see the TODO).
+//
+// Zero-cost when off: recordReq is a single boolean check. Enable with
+//   localStorage.setItem("bitvid:reqTrace", "1")  (then reload)
+// or automatically in dev mode. Read results from the periodic
+// "[req-trace]" logs or on demand via window.__bitvidReqTrace.report().
+
+import { isDevMode } from "../config.js";
+import { userLogger } from "../utils/logger.js";
+
+const STORAGE_FLAG = "bitvid:reqTrace";
+const REPORT_WINDOW_MS = 10000;
+const PLUMBING_FRAME = /reqTelemetry\.js|toolkit\.js|relaySubscriptionService|subscriptionManager|nostrPublish\.js|node_modules|^Error/i;
+
+function readStorageFlag() {
+  try {
+    return (
+      typeof localStorage !== "undefined" &&
+      localStorage.getItem(STORAGE_FLAG) === "1"
+    );
+  } catch (error) {
+    return false;
+  }
+}
+
+// First stack frame that is application code rather than pool plumbing.
+export function extractCallSite(stack) {
+  if (typeof stack !== "string" || !stack) {
+    return "unknown";
+  }
+  for (const rawLine of stack.split("\n")) {
+    const line = rawLine.trim();
+    if (!line || PLUMBING_FRAME.test(line)) {
+      continue;
+    }
+    // "at fn (url:line:col)" / "fn@url:line:col" → keep it short but unique
+    // enough to identify the module (strip origin, keep path:line).
+    const match = line.match(/((?:[\w./-]+\/)?[\w.-]+\.m?js):(\d+)(?::\d+)?/);
+    if (match) {
+      const fnMatch = line.match(/at ([\w.<>$[\]]+) |^([\w.<>$[\]]+)@/);
+      const fn = fnMatch ? fnMatch[1] || fnMatch[2] : "";
+      return `${fn ? `${fn} ` : ""}${match[1]}:${match[2]}`.trim();
+    }
+    return line.slice(0, 120);
+  }
+  return "unknown";
+}
+
+export function createReqTelemetry({
+  now = () => Date.now(),
+  log = (payload) => userLogger.info("[req-trace]", payload),
+  windowMs = REPORT_WINDOW_MS,
+} = {}) {
+  const state = {
+    enabled: false,
+    entries: new Map(), // key: `${kinds}|${callSite}` → { kinds, callSite, count, relayFanout }
+    total: 0,
+    relayFanout: 0,
+    windowStart: 0,
+    timer: null,
+  };
+
+  const reset = () => {
+    state.entries.clear();
+    state.total = 0;
+    state.relayFanout = 0;
+    state.windowStart = now();
+  };
+
+  const record = (relayCount, filters, stack) => {
+    if (!state.enabled) {
+      return;
+    }
+    const list = Array.isArray(filters) ? filters : filters ? [filters] : [];
+    const kinds = Array.from(
+      new Set(
+        list.flatMap((filter) =>
+          Array.isArray(filter?.kinds) ? filter.kinds : [],
+        ),
+      ),
+    )
+      .sort((a, b) => a - b)
+      .join(",");
+    const callSite = extractCallSite(stack);
+    const key = `${kinds || "?"}|${callSite}`;
+    const entry = state.entries.get(key) || {
+      kinds: kinds || "?",
+      callSite,
+      count: 0,
+      relayFanout: 0,
+    };
+    entry.count += 1;
+    entry.relayFanout += Number.isFinite(relayCount) ? relayCount : 0;
+    state.entries.set(key, entry);
+    state.total += 1;
+    state.relayFanout += Number.isFinite(relayCount) ? relayCount : 0;
+  };
+
+  const report = ({ emit = true } = {}) => {
+    const elapsedMs = Math.max(1, now() - state.windowStart);
+    const rows = Array.from(state.entries.values()).sort(
+      (a, b) => b.count - a.count,
+    );
+    const payload = {
+      windowSeconds: Math.round(elapsedMs / 100) / 10,
+      totalSubs: state.total,
+      totalRelayReqs: state.relayFanout,
+      perSecond: Math.round((state.relayFanout / elapsedMs) * 10000) / 10,
+      byKindsAndCaller: rows.slice(0, 15).map((row) => ({
+        kinds: row.kinds,
+        caller: row.callSite,
+        subs: row.count,
+        relayReqs: row.relayFanout,
+      })),
+    };
+    if (emit && state.total > 0) {
+      log(payload);
+    }
+    return payload;
+  };
+
+  const start = () => {
+    if (state.enabled) {
+      return;
+    }
+    state.enabled = true;
+    reset();
+    if (typeof setInterval === "function" && !state.timer) {
+      state.timer = setInterval(() => {
+        report();
+        reset();
+      }, windowMs);
+      if (typeof state.timer?.unref === "function") {
+        state.timer.unref();
+      }
+    }
+  };
+
+  const stop = () => {
+    state.enabled = false;
+    if (state.timer) {
+      clearInterval(state.timer);
+      state.timer = null;
+    }
+  };
+
+  return {
+    get enabled() {
+      return state.enabled;
+    },
+    start,
+    stop,
+    reset,
+    record,
+    report,
+  };
+}
+
+const defaultTelemetry = createReqTelemetry();
+
+// Auto-arm in dev mode or when the localStorage flag is set; expose a console
+// handle either way so it can be started on a production build too.
+if (isDevMode || readStorageFlag()) {
+  defaultTelemetry.start();
+}
+if (typeof window !== "undefined") {
+  window.__bitvidReqTrace = defaultTelemetry;
+}
+
+// Hot-path hook for the pool shim: one boolean check when tracing is off.
+export function recordReq(relayCount, filters) {
+  if (!defaultTelemetry.enabled) {
+    return;
+  }
+  defaultTelemetry.record(relayCount, filters, new Error().stack);
+}
+
+export default defaultTelemetry;

js/nostr/toolkit.js

@@ -3,6 +3,7 @@
 import { isDevMode } from "../config.js";
 import { nostrToolsReady } from "../nostrToolsBootstrap.js";
 import { devLogger, userLogger } from "../utils/logger.js";
+import { recordReq } from "./reqTelemetry.js";
 
 /**
  * The default relay set bitvid bootstraps with before loading a user's
@@ -524,6 +525,10 @@ export function shimLegacySimplePoolMethods(pool) {
       const { relayList, filterList, requests } =
         createLegacySubscriptionContext(relays, filters);
 
+      // #9 REQ tracer: every sub/list passes through here — record kinds,
+      // fan-out, and the emitting call site (no-op unless tracing is armed).
+      recordReq(relayList.length, filterList);
+
       const listeners = {
         event: new Set(),
         eose: new Set(),

tests/req-telemetry.test.mjs

@@ -0,0 +1,97 @@
+// #9: the cold-login REQ storm's remaining emitters are unpinned, so a
+// dev-gated tracer at the pool.sub choke point aggregates every subscription
+// by kinds + emitting call site. These tests cover the aggregation, the
+// call-site extraction (must skip pool plumbing frames), and that the hot
+// path is a no-op while tracing is off.
+//
+// test_integrity_note:
+//   change_type: ["new_tests"]
+//   scenarios:
+//     - id: SCN-req-trace-aggregation
+//       given: "a telemetry instance with an injected clock and log sink"
+//       when: "subs with various kinds/relay counts are recorded and report() runs"
+//       then: "rows are grouped by kinds+caller, sorted by count, with correct totals and REQ/s"
+//   observable_outcomes:
+//     - "disabled instance records nothing"
+//     - "report() totals equal the recorded subs and relay fan-out"
+//     - "plumbing frames (toolkit/relaySubscriptionService) never become the caller"
+//   determinism_controls:
+//     - "injected now(); no interval timers exercised; synthetic stacks"
+//   anti_cheat_rationale:
+//     prevents: ["hard-coded return value", "over-mocking internal logic"]
+//   relaxation:
+//     did_relax_any_assertion: false
+
+import "./test-helpers/setup-localstorage.mjs";
+import test from "node:test";
+import { strict as assert } from "node:assert";
+import {
+  createReqTelemetry,
+  extractCallSite,
+} from "../js/nostr/reqTelemetry.js";
+
+const STACK = (site) =>
+  [
+    "Error",
+    "    at recordReq (http://x/js/nostr/reqTelemetry.js:180:5)",
+    "    at legacySub (http://x/js/nostr/toolkit.js:529:7)",
+    `    at ${site}`,
+  ].join("\n");
+
+test("records aggregate by kinds + caller and report totals are honest", () => {
+  let t = 0;
+  const logs = [];
+  const telem = createReqTelemetry({
+    now: () => t,
+    log: (payload) => logs.push(payload),
+  });
+  telem.start();
+  t = 0;
+  telem.reset();
+
+  for (let i = 0; i < 3; i += 1) {
+    telem.record(8, [{ kinds: [30000], authors: ["a"] }], STACK("loadLists (http://x/js/subscriptions.js:757:10)"));
+  }
+  telem.record(4, [{ kinds: [0] }, { kinds: [10050] }], STACK("dmBoot (http://x/js/services/dmNostrService.js:127:3)"));
+
+  t = 5000; // 5s window
+  const payload = telem.report({ emit: true });
+
+  assert.equal(payload.totalSubs, 4);
+  assert.equal(payload.totalRelayReqs, 28, "3×8 + 4 relay-level REQs");
+  assert.equal(payload.perSecond, 5.6, "28 REQs over 5s");
+  assert.equal(payload.byKindsAndCaller[0].kinds, "30000");
+  assert.equal(payload.byKindsAndCaller[0].subs, 3);
+  assert.match(payload.byKindsAndCaller[0].caller, /subscriptions\.js:757/);
+  assert.equal(payload.byKindsAndCaller[1].kinds, "0,10050");
+  assert.match(payload.byKindsAndCaller[1].caller, /dmNostrService\.js:127/);
+  assert.equal(logs.length, 1, "report emitted through the injected sink");
+});
+
+test("disabled tracer records nothing; stop() disarms a started one", () => {
+  const telem = createReqTelemetry({ now: () => 0, log: () => {} });
+  telem.record(8, [{ kinds: [30000] }], STACK("x (http://x/js/a.js:1:1)"));
+  assert.equal(telem.report({ emit: false }).totalSubs, 0, "off by default");
+
+  telem.start();
+  telem.record(2, [{ kinds: [7] }], STACK("x (http://x/js/a.js:1:1)"));
+  telem.stop();
+  telem.record(2, [{ kinds: [7] }], STACK("x (http://x/js/a.js:1:1)"));
+  assert.equal(telem.report({ emit: false }).totalSubs, 1, "no records after stop");
+});
+
+test("call-site extraction skips pool plumbing and keeps module:line", () => {
+  assert.match(
+    extractCallSite(STACK("refresh (http://x/js/services/moderationService.js:843:20)")),
+    /moderationService\.js:843/,
+  );
+  // Plumbing-only stack falls back to unknown rather than blaming the shim.
+  assert.equal(
+    extractCallSite(
+      "Error\n    at legacySub (http://x/js/nostr/toolkit.js:529:7)\n    at ensureSubscription (http://x/js/services/relaySubscriptionService.js:158:1)",
+    ),
+    "unknown",
+  );
+  assert.equal(extractCallSite(""), "unknown");
+  assert.equal(extractCallSite(undefined), "unknown");
+});

todo/TODO_2026-06-20_pre-launch.md

@@ -712,6 +712,15 @@ toward freshness and looked identical. Gave each a structural identity:
       ones (DM relays, interest sets) until after first render. Multi-subsystem +
       sensitive (trust) → do as a dedicated perf pass, not a rushed change.
       Source still to pin: the loop issuing 30000/30002/30005/30015 per contact.
+- [x] **REQ tracer SHIPPED (2026-07-03)** to pin those emitters empirically —
+      static search found NO per-contact list loops (mutes already batched), so
+      the hypothesis needs data. `js/nostr/reqTelemetry.js` hooks the shimmed
+      `pool.sub` choke point (every sub/list flows through it) and aggregates
+      kinds + relay fan-out + emitting call site per 10s window. Zero-cost off.
+      **To trace:** on unstable run `localStorage.setItem("bitvid:reqTrace","1")`,
+      reload (cold login), read the `[req-trace]` console logs (or
+      `window.__bitvidReqTrace.report()`); the top rows name the emitters and
+      the batching/deferral pass follows directly from that data.
 
 ### 22. Anti-spam: validate npub on application / submission forms
 - [x] **DONE 2026-06-24.** Added a shared, testable NIP-19 validator