Files
bitvid/tests/req-telemetry.test.mjs
T
thePR0M3TH3ANandClaude Fable 5 096fe12c19 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]>
2026-07-03 21:02:27 -04:00

98 lines
3.9 KiB
JavaScript
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
// #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");
});