From 096fe12c19c84a4e4d7cf43bd1a6bb06c0fa66b9 Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Fri, 3 Jul 2026 21:01:45 -0400 Subject: [PATCH] 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 --- js/nostr/reqTelemetry.js | 184 +++++++++++++++++++++++++++++ js/nostr/toolkit.js | 5 + tests/req-telemetry.test.mjs | 97 +++++++++++++++ todo/TODO_2026-06-20_pre-launch.md | 9 ++ 4 files changed, 295 insertions(+) create mode 100644 js/nostr/reqTelemetry.js create mode 100644 tests/req-telemetry.test.mjs diff --git a/js/nostr/reqTelemetry.js b/js/nostr/reqTelemetry.js new file mode 100644 index 00000000..16ad768f --- /dev/null +++ b/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; diff --git a/js/nostr/toolkit.js b/js/nostr/toolkit.js index 05d47e0b..b7e21855 100644 --- a/js/nostr/toolkit.js +++ b/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(), diff --git a/tests/req-telemetry.test.mjs b/tests/req-telemetry.test.mjs new file mode 100644 index 00000000..c98e1303 --- /dev/null +++ b/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"); +}); diff --git a/todo/TODO_2026-06-20_pre-launch.md b/todo/TODO_2026-06-20_pre-launch.md index a27434f7..91dfedbb 100644 --- a/todo/TODO_2026-06-20_pre-launch.md +++ b/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