diff --git a/CHANGELOG.md b/CHANGELOG.md index 68c5b475..cc2cf3ed 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,8 +5,10 @@ **An agent no longer loses its key to the 0.13 → by-id upgrade.** An XMesh review of `lib/config.js` 0.14.2 returned "do not ship" with 13 findings. Each was checked by running it in a sandbox state dir; 0.14.3 fixes the ones that lose or expose a key and the small ones beside them, by reading the state of an identity only from records committed in one -atomic step (see "Identity and on-disk state"). The wire is unchanged; the public surface gains `relocation.abortExport` -and `IdentityExportPendingError`. +atomic step (see "Identity and on-disk state"). The wire gains two sealed control frames for flow control, `cmb-budget` +and `cmb-refused`, which a 0.14.2 node ignores (see "Transport and node lifecycle", Flow control); the public surface +gains `relocation.abortExport`, `IdentityExportPendingError`, `node.undelivered()`, `node.flowStatus()`, the +`undelivered` event and `delivery.queued`. ### What was wrong @@ -176,7 +178,9 @@ An independent security review (R2) of the 0.14 core reproduced each finding bel (2,048 entries, 32 M characters); the inbox holds at most 32 M characters (read items make room, oldest first; an unread one never goes, and a delivery that does not fit is refused and counted, `inbox-full-refused`). The review's 24 records of 2 × 200 KB: 15 s CPU before, 0.4 s now. The store itself is still unbounded on disk by default - (retention is unlimited unless configured); the size budget bounds how fast one session can grow it. + (retention is unlimited unless configured); the size budget bounds how fast one session can grow it. Past either + budget a record now waits in the session's queue instead of being dropped (Flow control, under "Transport and node + lifecycle"). - Gossip signature checks are bounded whatever the number of sessions: every new attestation, checkpoint, witness or authority statement takes one global token before verification, through the sending peer's fair share. The ceiling after verification is gone (R2-4). @@ -331,10 +335,12 @@ is unchanged except where a line says so. delivered: `node.pendingDeliveries()` lists it, `status().pendingDeliveries` counts it, and metrics say each step (`cmb-requeued`, `cmb-redelivered`, and `cmb-undelivered` with reason `redelivery-overflow` or `node-stopped` when it is dropped). The list is bounded: 2048 records or - 8 MiB a peer, 10,000 in all, the oldest dropped first. A receiver surfaces a record once for the life + 8 Mi characters a peer, 10,000 in all; a record past it is not held (said undelivered, `held-full`) and nothing held + is pushed out for it (Flow control, below). A receiver surfaces a record once for the life of its store (the delivery ledger), so a record offered twice is not delivered twice. **The residual:** a frame a socket has written and the network, the relay or the relay's way to the peer then loses - is still lost and still reads as dispatched; only an end-to-end receipt closes that, which is + (or that is still unread in the receiver's socket when the receiver closes it) is still lost and + still reads as dispatched; only an end-to-end receipt closes that, which is protocol work. The held list is process memory: a stop drops it (said as undelivered); the record stays in the sender's store. - **The relay connection's ceiling is 8 MiB; the frame bound is per message (R3-1, R3-2).** A message @@ -375,6 +381,80 @@ is unchanged except where a line says so. - `discovery.stop()` closes the connections it accepted and has not handed on, and its bounded wait no longer holds the process open. +#### Flow control (directed and room records) + +**What was wrong.** A receiver bounds what one session's records cost it: a record budget per session by +count (8 a second after a burst of 32, security review D) and, new in this release, by size (128 KiB of +record text a second after 1.5 MiB, R2-3), behind a pre-verification lane (32 a second, burst 128; 1 MiB/s, +burst 4 MiB). A record past either was DROPPED, unchecked or unevaluated, while its sender reported it +dispatched, and nothing offered it again. Measured on the first 0.14.3 candidate (9f6847c), real nodes on one +host: 49 directed messages sent in a burst, 32 delivered over the LAN and 38 over a relay (15 ms apart, the +review's r-msgloss; 0.14.2 the same); 12 records of 200 KB, 7 (0.14.2 delivered 12: it had no size budget); +40 of 50 KB, 30; 120 records held across a relay drop and re-offered by the new held-record path (the pacer +back at 20/s burst 200; over the LAN every held record was written at once), 38, the sender reporting 115 +redelivered and nothing pending. + +**The design.** The budget exists to bound CPU and memory; it must not lose honest traffic (`lib/flow-control.js`). + +- **The receiver queues, it does not drop.** Every record a session brings is admitted (verified, + evaluated, surfaced) only once both lanes hold it and nothing of that session waits ahead of it; + otherwise it waits in the session's queue, in order, and is admitted as the lanes refill. What the + budget bounds is exactly as before. The queue holds at most 64 s of the budget per session (512 + records, 8 Mi characters) and 4,096 records or 32 Mi characters in all. A record that arrived on a + session that has since closed is still admitted; one whose peer is no longer admitted (the door, a + penalty) is dropped and counted (`cmb-queue-dropped`). Counted: `cmb-queued`, and + `status().flowControl.receiver` (queued now, peaks, admitted late, refused, notices, cut). +- **Past the queue a record is refused and its sender told.** A sealed control frame + `{ type: 'cmb-refused', assertionIds: [≤ 256], retryAfterMs }` names the refused records (by the + assertionId the record carries) and when to try again: the time the session's queue needs to drain + at its budget, or, when every session's queue together was full, the longest one's; 1 s to 64 s. At + most one notice a second per peer; refusals past what four notices carry are counted, not listed; a + notice owed to a peer with no open session waits a minute for its next one. Counted: + `cmb-queue-refused`, `cmb-refusal-sent`, `cmb-refusal-unsent`. A node stopping refuses what waits + in its queue and tells each sender, so the records are offered again to its next session. +- **A peer that keeps on is cut.** One that, told, sends more than 512 records past its OWN queue + before that queue has drained (it sent more than 64 s of its budget ahead of it, and kept on) is + closed and not admitted again for 60 s, as a forgery is (`record-flood-cut`). A sender refused + because every session's queue together was full is not at fault and never counts toward it, and a + peer whose queue drains starts over. A paced sender never fills its own queue. +- **The receiver advertises its budget.** Once a session is admitted each side sends + `{ type: 'cmb-budget', recordsPerSecond, recordsBurst, charsPerSecond, charsBurst, queueRecords, + queueChars }` (8, 32, 131072, 1572864, 512, 8388608), sealed, first in the greeting. A frame with a + member outside these, or a value that is not a finite number in range, is refused and counted + (`malformed`), as a malformed `cmb-refused` is. +- **The sender paces every record to it.** Directed and room records, messages, a sleeping peer's + queued records, and the held records re-offered after a relay or LAN drop all go through the peer's + held list, oldest first, and are written to its session only within the budget that peer advertised + for it (each end starts a session with full buckets; anchors spend it too; an advertisement that + arrives late starts from the burst less what was already sent). A peer that advertises nothing + (0.14.2 and older) is paced to the 0.14.2 budget with a quarter kept as margin, 6 a second after 24, + and no size budget: 0.14.2 drops past 8/32, and a sender pacing exactly to it loses a record whenever + two arrive closer together than they were written. A record counts as dispatched only when it is + written: `delivery.dispatched` counts those, `delivery.queued` the copies held for the budget (a + directed send held is not undelivered), `pendingDeliveries()` lists every held record with its state + (`waiting`, `refused`, `written` to a relay pacer). A refused record goes back on the held list in + its place, nothing more goes to that session until the retry-after, and it is offered again (to that + peer only: a room record other peers took is not sent to them again); after 8 retries refused, or + once it is 23 h old by its signed timestamp (a receiver refuses a directed record older than 24 h), + it is given up: `cmb-undelivered`, the `undelivered` event, and `node.undelivered()` (the last 256). + A record past the held list's bound is refused at once (its send says `held-full`). +- **Old peers both ways.** A 0.14.2 node ignores both frames (§7.3: an unknown type is ignored); run + against a `git archive` of 0.14.2 (fe285a3) it logs and counts nothing for them. A 0.14.3 sender to a + 0.14.2 receiver: 49 messages, 12 × 200 KB, 40 × 50 KB and 120 records across a relay drop all + delivered, the receiver dropping none. A 0.14.2 sender (it paces nothing and hears nothing) to a + 0.14.3 receiver: 49 messages, 12 × 200 KB and 40 × 50 KB all delivered from the queue; past the queue + its records are refused (it never offers them again) and past the cut it is closed, so a new receiver + still bounds an old sender. + +**Measured now** (the same runs, 0.14.3): 49 messages over the LAN and over the relay, 49; 12 × 200 KB, +12; 40 × 50 KB, 40; 120 across a relay drop (the reviewer's script against sym-relay `origin/main` on +127.0.0.1, the relay process killed and restarted), 120, the sender's counts true (nothing pending, +nothing undelivered, every record it held then written), the receiver queueing at most one record at a +time (timer jitter, admitted within milliseconds); 120 across a LAN drop, 120. Each exactly once. A flood +of 2,300 records from a peer that ignores everything: at most 32 + 8/s evaluated, at most 512 waiting, +the rest refused and the peer told (each notice ≤ 256 ids, retry-after 64 s), then cut. 40 records of +400 K: at most 8 Mi characters waiting. + #### Known, not fixed here - **R3-8, one identity in several rooms in one process** (what XMesh's observer does): the inbox is @@ -382,10 +462,14 @@ is unchanged except where a line says so. design call; unchanged. Related: in a hot-swap the first node's stop() releases the identity lock file the second still relies on (an in-process re-acquisition gets a release that does nothing). - **End-to-end delivery receipts** (protocol work), and so the residual above. -- **A receiver drops records past its own record budget** (8 a second, burst 32, per session: security - review D) unevaluated while the sender reports them dispatched. Of R3's 260 directed records sent at - once, 55 were accepted in one run with no relay drop at all; R3's "227 lost after a drop" counts - these too. The tests here stay under the budget. +- (Was listed here in the first 0.14.3 candidate: a receiver dropped records past its own record budget, + unevaluated, while the sender reported them dispatched. Fixed, see Flow control above.) +- **Order across a refusal is not kept.** A receiver refuses a record only past its queue; a record the + sender wrote before the refusal notice reached it can be taken once the queue frees a slot, ahead of + the refused one, which the sender offers again later in its place. Within the budget (what a paced + sender never leaves) a session's records are admitted in the order they arrived. MMP promises no + application-level order; keeping it across refusals would mean refusing records inside the bound, + which costs a 0.14.2 sender (it never offers a refused record again) records it would otherwise keep. - **mesh-channel exits on `identity-collision`** (server.js), so one spoofed 4004 still stops a channel host until it exits on `info.pingPong` only. - A token holder that keeps claiming a nodeId keeps that member off the relay most of the time; only a @@ -403,6 +487,38 @@ is unchanged except where a line says so. and padded-roster attacks no longer close the victim's connection on 0.5.2 (the current relay already bounds both), and a member evicted by a spoofed 4004 is back on either relay after its retry. - `tests/relay-state.test.js`: the 4004 and 4006 cases now pin the long-backoff retry. +- **Flow control:** `tests/flow-control.test.js` (8, real nodes: the LAN over TCP on the loopback, the relay over a + WebSocket relay): the bursts, both drops and both old-peer directions above, each delivered exactly once with the + sender's counts true; all 8 fail on 9f6847c (a `git archive` of it): 32 of 49 messages over the LAN, 31 of 40 × + 50 KB, 38 of 49 over the relay, 38 of 120 across the relay drop, 32 of 120 across the LAN drop, and with the old + peer at either end 32 of 49 messages and at most 1 of 12 × 200 KB. + `tests/flow-control-bounds.test.js` (27): the queue's bounds per session and in all, by count and by size; the door + and the penalties for what waits; arrival order; the cut and its episodes; the pre-verification lane for copies of + a delivered record; the notice's rate; a stopping receiver; the advertisement and malformed frames; the legacy + pacing and its margin; a late advertisement; anchors; refusals (held again in place, the back-off, on a new + session, given up after 8, a room record retried to one peer only, a refusal of nothing held, one refused while in + the relay pacer); the age bound; the held list's bounds; the buckets' clock. 26 of the 27 fail on 9f6847c (most + because what they check is new); the one that passes pins what must not change, a write the session refuses + outright reported at once as before. The R2-3 and record-flood + tests (`security-0.14.3`, `core-secure-review`) and the held-list bound (`relay-redelivery`) now pin waiting, and a + held record never pushed out, instead of dropping. **Mutation check:** 52 mutants of `lib/flow-control.js`, + `lib/frame-handler.js` and `lib/node.js`, one per guard the design adds (the queue's FIFO and budget gate, its four + bounds, the door and the two penalties at the drain, the drain's wait, the cut's threshold, episode, reset and + told-in-episode, the notice's schedule, rate, id cap and pending cap, the retry-after's clamp and others-full, the + stop notice, the clock, the legacy margin, the advertisement's lower bound, the back-off and size pacing, six frame + checks, the two lane spends and the gate, advertising and applying the budget, pacing, not-before, the refusal + limit, both age checks, the held list's two bounds, the sent window's age and per-peer key, placement in order, the + refused-in-pacer case, the back-off call, a fresh write failure, the anchor spend): every one is caught. Five + survived a first run: four were caught once the tests measured the right thing (the drain's wait and the record + lane's spend, which the flood's cut had masked; the notice timer's spin; the sent window's per-peer key, which only + shows when the refusing peer is not the last one written); the fifth was a guard no input could reach (an own-queue + reason beside the episode, which already implies it) and was removed, its mutant replaced by one on the episode. + **Runs:** full suite on macOS (Node 22, `--test-concurrency=2`): 1686 tests, 1682 pass, 0 fail, 4 skipped; + integration 6 of 6; `node scripts/gate-two-stock-nodes.mjs` passed; `npm audit` 0 vulnerabilities; the two + flow-control files with the four changed ones (95 tests) pass in `node:22-slim` (22.23.3) and `node:20-slim` + (20.20.2); CI (Linux, Node 20 and 22): 1686 tests, 1683 pass, 0 fail, 3 skipped. The bursts and drops above were + also run as scripts against a `git archive` of 0.14.2 (fe285a3) and of 9f6847c, both directions, over the LAN and + over sym-relay `origin/main` (2b23444) on 127.0.0.1. ## 0.14.2 — 2026-10-14 diff --git a/SECURITY.md b/SECURITY.md index c7e716bf..d22eb0c0 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -240,7 +240,13 @@ Every store a peer can feed has a fixed bound. Reaching one never stops the node one sealed frame. This node mints nothing larger, and refuses a received record over any limit before anything validates, verifies or encodes it; a sealed frame longer than a 720 KiB record can produce (983,062 base64url characters) is refused before it is opened. At most 8 new records a - second per session are evaluated (burst 32). + second per session are evaluated (burst 32; and 128 KiB of record text a second, burst 1.5 MiB), + and at most 32 a second checked before verification (burst 128; 1 MiB/s, burst 4 MiB). Past either + a record waits in the session's queue, in order (0.14.3): at most 512 records or 8 Mi characters a + session, 4,096 records or 32 Mi characters in all. Past the queue it is refused unchecked and its + sender told (`cmb-refused`, at most one notice a second per peer, at most 256 records named in one); + a peer that, told, keeps sending more than 512 records past its own queue before that queue drains + is closed and not admitted again for 60 s. - **Wake channels**: at most 1,024, learned only from a confirmed session's own nodeId (a peer's word about another node is never stored), dropped after 30 days unseen; when the table is full a new first-hand channel displaces the least recently seen one of the weakest source, so many diff --git a/lib/flow-control.js b/lib/flow-control.js new file mode 100644 index 00000000..2e19f334 --- /dev/null +++ b/lib/flow-control.js @@ -0,0 +1,520 @@ +'use strict'; + +/** + * @module @sym-bot/sym/flow-control + * @description Flow control for directed and room records (sym 0.14.3). + * + * A receiver bounds what one session's records cost it: a record budget per session, by count (8 a + * second after a burst of 32, security review D) and by size (128 KiB of record text a second after + * 1.5 MiB, R2-3), before SVAF evaluates anything. Until 0.14.3 a record past the budget was DROPPED + * unevaluated while its sender reported it dispatched, and nothing offered it again: 49 directed + * messages sent in a burst reached the receiver as 38, 12 records of 200 KB as 7, and 120 records + * held across a relay drop as 37. The budget is there to bound CPU and memory; it must not lose + * honest traffic. So: + * + * RECEIVER. A record past the budget is QUEUED, per session, in arrival order, and admitted + * (verified, evaluated, surfaced) as the budget refills: it is delayed, never dropped. The queue is + * bounded per session (QUEUE_SECONDS of the budget: 512 records, 8 Mi characters) and in all + * (QUEUE_TOTAL_*). Only past a bound is a record refused, and then the receiver tells the sender in + * a sealed control frame, `cmb-refused`, naming the refused assertionIds and a retry-after. A peer + * that keeps sending past the bound after it was told is cut (closed, and not admitted again for a + * minute): an honest sender never is, it paces. + * + * ADVERTISEMENT. Once a session is admitted, each side tells the other its budget in a sealed + * control frame, `cmb-budget` (the rate and burst by count and by size, and the queue bound). + * + * SENDER. Records to a peer — directed or room, fresh or held — are written to its session within + * the budget that peer advertised (one that advertises nothing, 0.14.2 and older, is paced to the + * 0.14.2 budget, with a margin: it drops past it). What does not fit waits in the peer's held list + * and is written as the budget refills. A record counts as dispatched only once it is written + * within the budget; a refused one goes back to the held list and is retried after the retry-after, + * and after HELD_REFUSALS_MAX refusals or HELD_MAX_AGE_MS it is reported undelivered. + * + * Nothing here changes what a record costs once it is admitted: the budget, and what it bounds, are + * exactly as before. Only what happens past it changes. + * + * @copyright 2026 SYM.BOT. Apache 2.0 License. + */ + +// ── The receiver's record budget, per session ────────────────────────────────────────────────── + +/** Records one session has evaluated, at most: a burst, then a rate a second (security review D). */ +const RECORDS_PER_SECOND = 8; +const RECORDS_BURST = 32; +/** The record lane by size (R2-3): characters of record text a second, after a burst. */ +const RECORD_CHARS_PER_SECOND = 128 * 1024; +const RECORD_CHARS_BURST = 1536 * 1024; + +/** + * The queue in front of the budget holds at most QUEUE_SECONDS of it per session, by count and by + * size, so a record that is queued waits at most about that long; and at most QUEUE_TOTAL_* in all, + * whatever the number of sessions. (Characters, as the size budget counts them.) + */ +const QUEUE_SECONDS = 64; +const QUEUE_RECORDS = RECORDS_PER_SECOND * QUEUE_SECONDS; +const QUEUE_CHARS = RECORD_CHARS_PER_SECOND * QUEUE_SECONDS; +const QUEUE_TOTAL_RECORDS = 4096; +const QUEUE_TOTAL_CHARS = 32 * 1024 * 1024; + +/** + * A refusal notice (`cmb-refused`) goes to a peer at most once every REFUSAL_NOTICE_MS, naming at most + * REFUSAL_IDS_MAX assertionIds; at most REFUSAL_PENDING_MAX wait for the next one (past it a refusal + * is counted, not listed: only a sender past every bound gets there). Notices for a peer with no open + * session wait at most REFUSAL_PENDING_MS for its next one. + */ +const REFUSAL_NOTICE_MS = 1000; +const REFUSAL_IDS_MAX = 256; +const REFUSAL_PENDING_MAX = 4 * REFUSAL_IDS_MAX; +const REFUSAL_PENDING_MS = 60_000; +const REFUSAL_PEERS_MAX = 1024; +/** The retry-after a refusal carries: the time the session's queue needs to drain, within these. */ +const RETRY_AFTER_MIN_MS = 1000; +const RETRY_AFTER_MAX_MS = QUEUE_SECONDS * 1000; +/** + * A peer told, and still sending past the bound by more than this many records before its queue has + * drained, is cut (closed, and not admitted again for FLOOD_PENALTY_MS). An honest sender stops within + * the records it had in flight when the notice reached it, far fewer. + */ +const REFUSALS_BEFORE_CUT = QUEUE_RECORDS; +const FLOOD_PENALTY_MS = 60_000; + +/** The sealed control frames (lib/core/sealed-control.js carries them; a 0.14.2 node ignores both, §7.3). */ +const BUDGET_FRAME = 'cmb-budget'; +const REFUSED_FRAME = 'cmb-refused'; +const BUDGET_MEMBERS = Object.freeze(['type', 'recordsPerSecond', 'recordsBurst', 'charsPerSecond', 'charsBurst', 'queueRecords', 'queueChars']); +const REFUSED_MEMBERS = Object.freeze(['type', 'assertionIds', 'retryAfterMs']); +const ASSERTION_ID = /^asrt-[0-9a-f]{64}$/; + +// ── The sender ───────────────────────────────────────────────────────────────────────────────── + +/** + * What a sender paces a peer to before, or without, its advertisement: the 0.14.2 record budget (8 a + * second, burst 32; 0.14.2 had no size budget) with a quarter of it kept as a margin. A 0.14.2 + * receiver DROPS past its budget, and a sender pacing exactly to it loses a record whenever two arrive + * closer together than they were written (a relay's pacer, the network): the margin absorbs that. An + * advertising receiver queues, so it is paced exactly to what it says. + */ +const LEGACY_BUDGET = Object.freeze({ recordsPerSecond: 6, recordsBurst: 24, charsPerSecond: Infinity, charsBurst: Infinity, queueRecords: 0, queueChars: 0 }); +/** A refused record is retried at most this many times; a held one is given up at this age (signed). */ +const HELD_REFUSALS_MAX = 8; +/** Below the receiver's 24 h window for a directed record's signed age (frame-handler DIRECTED_WINDOW_MS). */ +const HELD_MAX_AGE_MS = 23 * 60 * 60 * 1000; +/** + * A record written to a peer is remembered this long (and at most SENT_WINDOW_MAX of them in all), so + * a refusal naming it can put it back on the held list. Refusals are sent within REFUSAL_NOTICE_MS of + * the record's arrival; a minute covers a slow relay several times over. + */ +const SENT_WINDOW_MS = 60_000; +const SENT_WINDOW_MAX = 20_000; +/** The most undelivered records `undelivered()` lists (the newest kept). */ +const UNDELIVERED_LOG_MAX = 256; + +/** What a record weighs for the size budgets: its texts and application data, in characters. */ +function recordChars(cmb) { + let n = 512; + const cats = cmb && typeof cmb === 'object' ? cmb.categories : null; + if (cats && typeof cats === 'object') { + for (const v of Object.values(cats)) { + if (typeof v === 'string') n += v.length; + else if (v && typeof v === 'object' && typeof v.text === 'string') n += v.text.length; + } + } + const md = cmb && typeof cmb === 'object' ? cmb.metadata : null; + if (md && typeof md === 'object') { + if (md.application && typeof md.application === 'object' && typeof md.application.data === 'string') n += md.application.data.length; + if (typeof md.createdBy === 'string') n += md.createdBy.length; + } + return n; +} + +/** Refill a bucket {tokens, at} to `now` at `rate` a second up to `burst`. A clock stepped back refills nothing and takes nothing. */ +function refillBucket(b, rate, burst, now) { + const elapsed = now - b.at; + if (elapsed > 0) b.tokens = Math.min(burst, b.tokens + (elapsed * rate) / 1000); + b.at = Math.max(b.at, now); + return b; +} + +/** Milliseconds until bucket `b` holds `need` (at most its burst), refilled to `now`; 0 when it does. */ +function bucketWait(b, rate, burst, need, now) { + refillBucket(b, rate, burst, now); + const n = Math.min(need, burst); + if (b.tokens >= n) return 0; + return Math.max(1, Math.ceil(((n - b.tokens) * 1000) / rate)); +} + +/** The advertisement this node sends: its record budget and its queue bound per session. */ +function budgetFrame({ recordsPerSecond = RECORDS_PER_SECOND, recordsBurst = RECORDS_BURST, charsPerSecond = RECORD_CHARS_PER_SECOND, charsBurst = RECORD_CHARS_BURST, queueRecords = QUEUE_RECORDS, queueChars = QUEUE_CHARS } = {}) { + return { type: BUDGET_FRAME, recordsPerSecond, recordsBurst, charsPerSecond, charsBurst, queueRecords, queueChars }; +} + +const finiteIn = (v, lo, hi) => typeof v === 'number' && Number.isFinite(v) && v >= lo && v <= hi; +/** + * A peer's `cmb-budget`, checked: the frame's members exactly, each a finite number in range. A rate + * below one record a minute is taken as one a minute (a receiver that advertises less only slows what + * it is sent; the held list's age bound still gives the records up). @returns {object|null} + */ +function parseBudgetFrame(f) { + if (!f || typeof f !== 'object' || Array.isArray(f)) return null; + // No member outside the schema; each member is checked below (a missing one is not a finite number). + if (!Object.keys(f).every((k) => BUDGET_MEMBERS.includes(k))) return null; + if (!finiteIn(f.recordsPerSecond, 0, 1e6) || !finiteIn(f.recordsBurst, 1, 1e7)) return null; + if (!finiteIn(f.charsPerSecond, 0, 1e12) || !finiteIn(f.charsBurst, 1, 1e12)) return null; + if (!finiteIn(f.queueRecords, 0, 1e7) || !finiteIn(f.queueChars, 0, 1e12)) return null; + return Object.freeze({ + recordsPerSecond: Math.max(f.recordsPerSecond, 1 / 60), + recordsBurst: f.recordsBurst, + charsPerSecond: Math.max(f.charsPerSecond, 1), + charsBurst: f.charsBurst, + queueRecords: f.queueRecords, + queueChars: f.queueChars, + }); +} + +/** A peer's `cmb-refused`, checked: the frame's members exactly. @returns {{ ids: string[], retryAfterMs: number }|null} */ +function parseRefusedFrame(f) { + if (!f || typeof f !== 'object' || Array.isArray(f)) return null; + if (!Object.keys(f).every((k) => REFUSED_MEMBERS.includes(k))) return null; + const ids = f.assertionIds; + if (!Array.isArray(ids) || ids.length < 1 || ids.length > REFUSAL_IDS_MAX || !ids.every((id) => typeof id === 'string' && ASSERTION_ID.test(id))) return null; + if (!Number.isInteger(f.retryAfterMs) || f.retryAfterMs < 0 || f.retryAfterMs > 3_600_000) return null; + return { ids: [...new Set(ids)], retryAfterMs: Math.min(Math.max(f.retryAfterMs, RETRY_AFTER_MIN_MS), RETRY_AFTER_MAX_MS) }; +} + +/** + * One session's outbound record budget, as its receiver sees it: two buckets (count and size), the + * peer's advertised budget once it has said it (LEGACY_BUDGET until then), and a back-off a refusal + * set. Both ends start a session with full buckets, so a sender that spends here never exceeds what + * the receiver holds for it. + */ +class OutboundBudget { + constructor(now = Date.now()) { + this.budget = LEGACY_BUDGET; + this.advertised = false; + this.count = { tokens: LEGACY_BUDGET.recordsBurst, at: now }; + this.chars = { tokens: LEGACY_BUDGET.charsBurst, at: now }; + this.spent = { records: 0, chars: 0 }; + this.backoffUntil = 0; + } + + /** + * The peer said its budget. The first time, the buckets start from what the receiver can at least + * hold now: its burst less everything sent on this session so far (it may hold more, never less). + * A later one changes the rates and keeps what the buckets hold, within the new bursts. + */ + apply(b, now = Date.now()) { + if (!this.advertised) { + this.count = { tokens: Math.max(0, b.recordsBurst - this.spent.records), at: now }; + this.chars = { tokens: Math.max(0, b.charsBurst - this.spent.chars), at: now }; + } else { + this.count = { tokens: Math.min(refillBucket(this.count, this.budget.recordsPerSecond, this.budget.recordsBurst, now).tokens, b.recordsBurst), at: now }; + this.chars = { tokens: Math.min(refillBucket(this.chars, this.budget.charsPerSecond, this.budget.charsBurst, now).tokens, b.charsBurst), at: now }; + } + this.budget = b; + this.advertised = true; + } + + /** Milliseconds until a record of `chars` may be written: 0 now. */ + wait(chars, now = Date.now()) { + const b = this.budget; + return Math.max( + this.backoffUntil > now ? this.backoffUntil - now : 0, + bucketWait(this.count, b.recordsPerSecond, b.recordsBurst, 1, now), + Number.isFinite(b.charsBurst) ? bucketWait(this.chars, b.charsPerSecond, b.charsBurst, chars, now) : 0, + ); + } + + /** Spend a record of `chars` (written). A record past what the buckets hold (an anchor) still spends. */ + take(chars, now = Date.now()) { + const b = this.budget; + refillBucket(this.count, b.recordsPerSecond, b.recordsBurst, now); + this.count.tokens -= 1; + if (Number.isFinite(b.charsBurst)) { + refillBucket(this.chars, b.charsPerSecond, b.charsBurst, now); + this.chars.tokens -= Math.min(chars, b.charsBurst); + } + this.spent.records += 1; + this.spent.chars += chars; + } + + /** The receiver refused records: nothing more is written to this session for `ms`. */ + backOff(ms, now = Date.now()) { + this.backoffUntil = Math.max(this.backoffUntil, now + ms); + } +} + +// ── The receiver's admission queue ───────────────────────────────────────────────────────────── + +/** + * Records past a session's budget, waiting for it to refill (one FIFO per session), and the refusal + * notices owed to peers. The owner (the frame handler) supplies the budget and the work: + * + * wait(session, chars, now) ms until the session's budget holds a record of `chars` (0: now) + * run(entry) admit one record now (spends the budget and processes it) + * admitted(entry) whether its peer is still admitted (the door, a penalty): or dropped + * sessionFor(peerId) the peer's open session for a notice, or null + * cut(session) the penalty for a session that keeps sending past the bound + * fail(entry, err) a record that threw while it was admitted from the queue + * metric(m), say(key, line) + */ +class RecordAdmission { + constructor(o) { + this._o = o; + this.limits = { queueRecords: QUEUE_RECORDS, queueChars: QUEUE_CHARS, totalRecords: QUEUE_TOTAL_RECORDS, totalChars: QUEUE_TOTAL_CHARS, refusalsBeforeCut: REFUSALS_BEFORE_CUT }; + this._sessions = new Set(); + this._notices = new Map(); + this.total = { records: 0, chars: 0 }; + this.stats = { queued: 0, admittedLate: 0, refused: 0, dropped: 0, notices: 0, noticedIds: 0, unlisted: 0, unsent: 0, cut: 0, peakRecords: 0, peakChars: 0 }; + } + + _queueOf(session) { + return session._admitQueue || (session._admitQueue = { items: [], head: 0, chars: 0, timer: null }); + } + + /** + * A record arrived on `session`. Admitted now when nothing of the session's waits and its budget + * holds it (what run returns is returned); otherwise queued behind what waits, or, past a bound, + * refused and the sender told. @returns {*} run's result, or undefined + */ + offer(session, peerId, peerName, msg, chars, now = Date.now()) { + const q = this._queueOf(session); + const waiting = q.items.length - q.head; + const entry = { session, peerId, peerName, msg, chars }; + if (waiting === 0 && this._o.wait(session, chars, now) === 0) return this._o.run(entry); + const L = this.limits; + if (waiting >= L.queueRecords || q.chars + chars > L.queueChars) return this._refuse(entry, 'session-queue-full', now); + if (this.total.records >= L.totalRecords || this.total.chars + chars > L.totalChars) return this._refuse(entry, 'queue-full', now); + q.items.push(entry); + q.chars += chars; + this.total.records++; + this.total.chars += chars; + this.stats.queued++; + if (this.total.records > this.stats.peakRecords) this.stats.peakRecords = this.total.records; + if (this.total.chars > this.stats.peakChars) this.stats.peakChars = this.total.chars; + this._sessions.add(session); + this._o.metric({ type: 'cmb-queued', from: peerName, peer: peerId, key: keyOf(msg), waiting: waiting + 1 }); + if (!q.timer) this._arm(session, q, this._o.wait(session, q.items[q.head].chars, now)); + return undefined; + } + + _arm(session, q, ms) { + q.timer = setTimeout(() => { q.timer = null; this._drain(session); }, Math.max(ms, 1)); + if (q.timer.unref) q.timer.unref(); + } + + _shift(session, q) { + const e = q.items[q.head]; + q.items[q.head] = undefined; + q.head++; + if (q.head > 64 && q.head * 2 > q.items.length) { q.items = q.items.slice(q.head); q.head = 0; } + q.chars -= e.chars; + this.total.records--; + this.total.chars -= e.chars; + return e; + } + + /** Admit what the budget now holds, in order; re-arm for the next. */ + _drain(session) { + const q = session._admitQueue; + if (!q) return; + while (q.items.length - q.head > 0) { + const head = q.items[q.head]; + if (!this._o.admitted(head)) { + this._shift(session, q); + this.stats.dropped++; + this._o.metric({ type: 'cmb-queue-dropped', from: head.peerName, peer: head.peerId, key: keyOf(head.msg), reason: 'not-admitted' }); + continue; + } + const now = Date.now(); + const w = this._o.wait(session, head.chars, now); + if (w > 0) { this._arm(session, q, w); return; } + const e = this._shift(session, q); + this.stats.admittedLate++; + try { this._o.run(e); } catch (err) { this._o.fail(e, err); } + } + q.items = []; + q.head = 0; + this._sessions.delete(session); + // The session's queue drained: a peer told and back within its budget starts over. + const n = this._notices.get(session.nodeId); + if (n) { n.refusedSinceTold = 0; n.toldAt = 0; n.episode = false; } + } + + _refuse(entry, reason, now) { + const { session, peerId, peerName, msg } = entry; + this.stats.refused++; + this._o.metric({ type: 'cmb-queue-refused', from: peerName, peer: peerId, key: keyOf(msg), reason }); + this._o.say(`${peerId}|queue-refused`, `CMBs from ${peerName} refused: past ${reason === 'queue-full' ? 'this node\'s queue for all sessions' : 'its session\'s queue'} (${this.limits.queueRecords} records or ${this.limits.queueChars} characters a session, ${this.limits.totalRecords} in all); the sender is told to retry`); + const n = this._noticeOf(peerId, now); + const id = msg && msg.cmb && msg.cmb.metadata ? msg.cmb.metadata.assertionId : null; + if (typeof id === 'string' && ASSERTION_ID.test(id)) { + if (n.ids.length < REFUSAL_PENDING_MAX) n.ids.push(id); + else this.stats.unlisted++; + } else { + this.stats.unlisted++; + } + // Only a peer past ITS OWN queue can be cut: it sent more than QUEUE_SECONDS of its budget ahead + // of it. A paced sender never does; one refused because every session's queue together is full + // (others filled it) is not at fault, and is only told when to retry. An EPISODE is the time a + // peer's own queue is full: it starts with such a refusal and ends when the queue drains. Told + // means a notice went out during the episode (one for its tail, sent after the queue drained, + // tells nothing about the next), and what it sends past the bound after that counts. + if (reason === 'queue-full') n.othersFull = true; + if (reason === 'session-queue-full') n.episode = true; + if (n.toldAt) { + n.refusedSinceTold++; + if (n.refusedSinceTold > this.limits.refusalsBeforeCut) { + n.refusedSinceTold = 0; + this.stats.cut++; + this._o.cut(session); + } + } + this._scheduleNotice(peerId, n, now); + return undefined; + } + + _noticeOf(peerId, now) { + let n = this._notices.get(peerId); + if (!n) { + if (this._notices.size >= REFUSAL_PEERS_MAX) { + const [oldId, old] = this._notices.entries().next().value; + this._dropNotice(oldId, old, 'too-many-peers'); + } + n = { ids: [], lastAt: 0, toldAt: 0, refusedSinceTold: 0, episode: false, othersFull: false, timer: null, since: now }; + this._notices.set(peerId, n); + } + return n; + } + + _dropNotice(peerId, n, why) { + if (n.timer) clearTimeout(n.timer); + if (n.ids.length) { + this.stats.unsent += n.ids.length; + this._o.metric({ type: 'cmb-refusal-unsent', peer: peerId, count: n.ids.length, reason: why }); + } + this._notices.delete(peerId); + } + + _scheduleNotice(peerId, n, now) { + if (n.timer || !n.ids.length) return; + const due = Math.max(0, n.lastAt + REFUSAL_NOTICE_MS - now); + n.timer = setTimeout(() => { n.timer = null; this.flush(peerId); }, due); + if (n.timer.unref) n.timer.unref(); + } + + /** + * The retry-after a notice carries: the time the session's own queue needs to drain at its budget, + * or, when a record was refused because every session's queue together was full, the time the + * longest one needs; within RETRY_AFTER_MIN_MS and RETRY_AFTER_MAX_MS. + */ + _retryAfter(session, othersFull) { + const drain = (q) => (q ? Math.max(((q.items.length - q.head) * 1000) / RECORDS_PER_SECOND, (q.chars * 1000) / RECORD_CHARS_PER_SECOND) : 0); + let ms = drain(session && session._admitQueue); + if (othersFull) for (const s of this._sessions) ms = Math.max(ms, drain(s._admitQueue)); + return Math.round(Math.min(Math.max(ms, RETRY_AFTER_MIN_MS), RETRY_AFTER_MAX_MS)); + } + + /** + * Send `peerId` what it is owed: one `cmb-refused` frame naming up to REFUSAL_IDS_MAX refused + * assertionIds, at most once every REFUSAL_NOTICE_MS (`force`: now, in as many frames as it takes). + * With no open session for the peer the notice waits for its next one, at most REFUSAL_PENDING_MS. + */ + flush(peerId, { force = false } = {}) { + const n = this._notices.get(peerId); + if (!n || !n.ids.length) return; + const now = Date.now(); + if (!force && n.lastAt && now - n.lastAt < REFUSAL_NOTICE_MS) { this._scheduleNotice(peerId, n, now); return; } + const session = this._o.sessionFor(peerId); + if (!session) { + if (now - n.since > REFUSAL_PENDING_MS) this._dropNotice(peerId, n, 'no-session'); + return; + } + do { + const ids = n.ids.splice(0, REFUSAL_IDS_MAX); + const retryAfterMs = this._retryAfter(session, n.othersFull); + let sent = false; + try { sent = session.trySend({ type: REFUSED_FRAME, assertionIds: ids, retryAfterMs }).ok === true; } catch { sent = false; } + if (!sent) { + this.stats.unsent += ids.length; + this._o.metric({ type: 'cmb-refusal-unsent', peer: peerId, count: ids.length, reason: 'send-failed' }); + break; + } + this.stats.notices++; + this.stats.noticedIds += ids.length; + n.lastAt = now; + n.since = now; + n.othersFull = false; + if (n.episode && !n.toldAt) n.toldAt = now; + this._o.metric({ type: 'cmb-refusal-sent', peer: peerId, count: ids.length, retryAfterMs }); + } while (force && n.ids.length); + if (n.ids.length) this._scheduleNotice(peerId, n, now); + } + + /** Whatever waits for the peer goes on its new session (called when one is admitted). */ + flushFor(peerId) { + const n = this._notices.get(peerId); + if (n && n.ids.length && !n.timer) this.flush(peerId); + } + + /** + * The node stops: every queued record is refused — its sender told, where a session is still open, + * so it offers the record again to this node's next session — and every timer cleared. + * @returns {number} the records refused + */ + stop() { + let n = 0; + for (const session of [...this._sessions]) { + const q = session._admitQueue; + if (!q) continue; + if (q.timer) { clearTimeout(q.timer); q.timer = null; } + while (q.items.length - q.head > 0) { + const e = this._shift(session, q); + n++; + const notice = this._noticeOf(e.peerId, Date.now()); + const id = e.msg && e.msg.cmb && e.msg.cmb.metadata ? e.msg.cmb.metadata.assertionId : null; + if (typeof id === 'string' && ASSERTION_ID.test(id)) notice.ids.push(id); + this.stats.refused++; + this._o.metric({ type: 'cmb-queue-refused', from: e.peerName, peer: e.peerId, key: keyOf(e.msg), reason: 'node-stopping' }); + } + q.items = []; + q.head = 0; + } + this._sessions.clear(); + for (const peerId of [...this._notices.keys()]) { + const notice = this._notices.get(peerId); + if (notice.timer) { clearTimeout(notice.timer); notice.timer = null; } + this.flush(peerId, { force: true }); + const left = this._notices.get(peerId); + if (left) this._dropNotice(peerId, left, 'node-stopped'); + } + this._notices.clear(); + this.total = { records: 0, chars: 0 }; + return n; + } + + /** What status() reports. */ + status() { + return { + queuedRecords: this.total.records, + queuedChars: this.total.chars, + queuedSessions: this._sessions.size, + ...this.stats, + limits: { ...this.limits }, + }; + } +} + +function keyOf(msg) { + const md = msg && msg.cmb && msg.cmb.metadata; + return md && typeof md.key === 'string' ? md.key : null; +} + +module.exports = { + RECORDS_PER_SECOND, RECORDS_BURST, RECORD_CHARS_PER_SECOND, RECORD_CHARS_BURST, + QUEUE_SECONDS, QUEUE_RECORDS, QUEUE_CHARS, QUEUE_TOTAL_RECORDS, QUEUE_TOTAL_CHARS, + REFUSAL_NOTICE_MS, REFUSAL_IDS_MAX, REFUSAL_PENDING_MAX, RETRY_AFTER_MIN_MS, RETRY_AFTER_MAX_MS, + REFUSALS_BEFORE_CUT, FLOOD_PENALTY_MS, + BUDGET_FRAME, REFUSED_FRAME, LEGACY_BUDGET, HELD_REFUSALS_MAX, HELD_MAX_AGE_MS, SENT_WINDOW_MS, SENT_WINDOW_MAX, UNDELIVERED_LOG_MAX, + recordChars, refillBucket, bucketWait, budgetFrame, parseBudgetFrame, parseRefusedFrame, + OutboundBudget, RecordAdmission, +}; diff --git a/lib/frame-handler.js b/lib/frame-handler.js index 3fee8140..d353d0c5 100644 --- a/lib/frame-handler.js +++ b/lib/frame-handler.js @@ -7,6 +7,10 @@ const { wireNodeId, wireName } = require('./wire-identity'); const { canonicalRecordV2_0 } = require('./core/record-canonical'); const { moodFrameReason } = require('./core/mood-frame'); const { ATTEST_FRAME, fromWireAttestation, fromWireCheckpoint, fromWireWitness, fromWireNodeStats } = require('./core/attestation'); +const { + RECORDS_PER_SECOND, RECORDS_BURST, RECORD_CHARS_PER_SECOND, RECORD_CHARS_BURST, + BUDGET_FRAME, REFUSED_FRAME, recordChars, refillBucket, bucketWait, budgetFrame, RecordAdmission, +} = require('./flow-control'); /** * @module @sym-bot/sym/frame-handler @@ -94,23 +98,25 @@ const DIRECTED_MARK = /#(asrt-|sd:|sig:)/; const { PEER_INFO_MAX } = require('./core/wake'); /** A record refused for its audience is said at most once per this many ms per peer and reason. */ -/** Refill a session's token bucket `slot` (a burst, then a rate a second) and return it. */ +/** + * A session's token bucket `slot` (a burst, then a rate a second), refilled to `now`. A clock stepped + * back refills nothing and takes nothing (lib/flow-control.js refillBucket). + */ function refill(session, slot, perSecond, burst, now) { const b = session[slot] || (session[slot] = { tokens: burst, at: now }); - b.tokens = Math.min(burst, b.tokens + ((now - b.at) * perSecond) / 1000); - b.at = now; - return b; + return refillBucket(b, perSecond, burst, now); } -/** Take one record from a count bucket and `chars` from a size bucket, both or neither. */ -function takeBoth(session, countSlot, countRate, countBurst, sizeSlot, sizeRate, sizeBurst, chars) { - const now = Date.now(); - const c = refill(session, countSlot, countRate, countBurst, now); - const s = refill(session, sizeSlot, sizeRate, sizeBurst, now); - const need = Math.max(0, Math.min(Number(chars) || 0, sizeBurst)); - if (c.tokens < 1 || s.tokens < need) return false; - c.tokens -= 1; - s.tokens -= need; - return true; +/** Milliseconds until a session's count lane holds one record and its size lane `chars` (0: now). */ +function laneWait(session, countSlot, countRate, countBurst, sizeSlot, sizeRate, sizeBurst, chars, now) { + return Math.max( + bucketWait(refill(session, countSlot, countRate, countBurst, now), countRate, countBurst, 1, now), + bucketWait(refill(session, sizeSlot, sizeRate, sizeBurst, now), sizeRate, sizeBurst, Math.max(0, Number(chars) || 0), now), + ); +} +/** Spend one record and `chars` (at most the size burst) of a session's two lanes. */ +function laneSpend(session, countSlot, countRate, countBurst, sizeSlot, sizeRate, sizeBurst, chars, now) { + refill(session, countSlot, countRate, countBurst, now).tokens -= 1; + refill(session, sizeSlot, sizeRate, sizeBurst, now).tokens -= Math.min(Math.max(0, Number(chars) || 0), sizeBurst); } /** Freeze an object graph (plain data: a structured clone of a record). */ @@ -124,16 +130,14 @@ function deepFreeze(o) { /** A directed record older than this by its signed timestamp is refused as a replay (finding G). */ /** - * New records one session has evaluated, at most: a burst, then a rate a second (security review D). - * A busy room's peer sends a few a second; one record costs the SVAF encoder tens of milliseconds. - */ -const RECORDS_PER_SECOND = 8; -const RECORDS_BURST = 32; -/** + * New records one session has evaluated, at most: a burst, then a rate a second (security review D; + * RECORDS_PER_SECOND and RECORDS_BURST, lib/flow-control.js). A busy room's peer sends a few a second; + * one record costs the SVAF encoder tens of milliseconds. + * * Records one session may have checked at all, before any work on them (final re-review, Finding 3): * the lane spent ahead of the schema check, key recomputation and signature verification, as the - * gossip lane is ahead of a statement's. Past it a record is dropped unchecked and unmarked. The burst - * covers a fetch answer (at most 64 records) and the anchor replay. + * gossip lane is ahead of a statement's. The burst covers a fetch answer (at most 64 records) and the + * anchor replay. */ const VERIFY_PER_SECOND = 32; const VERIFY_BURST = 128; @@ -142,30 +146,19 @@ const VERIFY_BURST = 128; * the SVAF encoder in proportion to its text, and a record may carry 720 KiB, so counting records let * one peer send 32 of the largest a second and buy CPU, memory and disk without bound. A record spends * its size in characters (category texts and application data; recordChars) from a second bucket on - * each lane, and passes only if both buckets hold enough. Each burst holds at least two records of the - * largest size, so any one record can pass. The usual peer sends records of a few KiB: far inside both. + * each lane (RECORD_CHARS_PER_SECOND and RECORD_CHARS_BURST for the record lane). Each burst holds at + * least two records of the largest size, so any one record can pass. The usual peer sends records of + * a few KiB: far inside both. + * + * PAST THE BUDGET A RECORD WAITS, IT IS NOT DROPPED (flow control, 0.14.3; lib/flow-control.js). Every + * record a session brings is admitted only when both lanes hold it and nothing of that session waits + * ahead of it; otherwise it is queued, in order, and admitted as the lanes refill, so the budget bounds + * the work exactly as before and loses nothing. Only past the queue's bound is a record refused, and its + * sender is told (`cmb-refused`) when to try again. Until 0.14.3 a record past either lane was dropped + * unchecked or unevaluated while its sender reported it dispatched. */ const VERIFY_CHARS_PER_SECOND = 1024 * 1024; const VERIFY_CHARS_BURST = 4 * 1024 * 1024; -const RECORD_CHARS_PER_SECOND = 128 * 1024; -const RECORD_CHARS_BURST = 1536 * 1024; -/** What a record weighs for the size budgets: its texts and application data, in characters. */ -function recordChars(cmb) { - let n = 512; - const cats = cmb && typeof cmb === 'object' ? cmb.categories : null; - if (cats && typeof cats === 'object') { - for (const v of Object.values(cats)) { - if (typeof v === 'string') n += v.length; - else if (v && typeof v === 'object' && typeof v.text === 'string') n += v.text.length; - } - } - const md = cmb && typeof cmb === 'object' ? cmb.metadata : null; - if (md && typeof md === 'object') { - if (md.application && typeof md.application === 'object' && typeof md.application.data === 'string') n += md.application.data.length; - if (typeof md.createdBy === 'string') n += md.createdBy.length; - } - return n; -} /** cmb-fetch serving bounds per session (security review D, fetch-amp). */ const FETCH_SERVE_PER_SECOND = 2; const FETCH_SERVE_BURST = 8; @@ -283,6 +276,8 @@ class FrameHandler { this._ledgerLines = 0; // lines the file holds this._ledgerEvicted = 0; this._loadLedger(); + // FLOW CONTROL (0.14.3): records past a session's budget wait here, in order, for it to refill. + this._admission = this._makeAdmission(); } /** @private Read the delivery ledger (`mark\texpiresAt` per line; a 0.14.2 line is a bare mark). */ @@ -450,16 +445,60 @@ class FrameHandler { * @private */ /** - * @private Take one of `session`'s pre-verification tokens and `chars` of its pre-verification size - * budget (R2-3), or neither. @returns {boolean} + * @private Milliseconds until both of `session`'s lanes hold a record of `chars` (0: now): the + * pre-verification lane and the record lane, each by count and by size (R2-3). A record is admitted + * only when this is 0 (see _handleMemoryShare), so neither lane is ever overdrawn. */ - _verifyBudget(session, chars = 0) { - return takeBoth(session, '_verifyBucket', VERIFY_PER_SECOND, VERIFY_BURST, '_verifyCharsBucket', VERIFY_CHARS_PER_SECOND, VERIFY_CHARS_BURST, chars); + _admitWait(session, chars = 0, now = Date.now()) { + return Math.max( + laneWait(session, '_verifyBucket', VERIFY_PER_SECOND, VERIFY_BURST, '_verifyCharsBucket', VERIFY_CHARS_PER_SECOND, VERIFY_CHARS_BURST, chars, now), + laneWait(session, '_recordBucket', RECORDS_PER_SECOND, RECORDS_BURST, '_recordCharsBucket', RECORD_CHARS_PER_SECOND, RECORD_CHARS_BURST, chars, now), + ); + } + + /** @private Spend `session`'s pre-verification lane for a record of `chars`: before any work on it. */ + _spendVerify(session, chars = 0, now = Date.now()) { + laneSpend(session, '_verifyBucket', VERIFY_PER_SECOND, VERIFY_BURST, '_verifyCharsBucket', VERIFY_CHARS_PER_SECOND, VERIFY_CHARS_BURST, chars, now); + } + + /** @private Spend `session`'s record lane for a new record of `chars`: before SVAF encodes anything. */ + _spendRecord(session, chars = 0, now = Date.now()) { + laneSpend(session, '_recordBucket', RECORDS_PER_SECOND, RECORDS_BURST, '_recordCharsBucket', RECORD_CHARS_PER_SECOND, RECORD_CHARS_BURST, chars, now); + } + + /** The record budget this node advertises to each admitted session (`cmb-budget`). */ + flowBudget() { + const L = this._admission.limits; + return budgetFrame({ recordsPerSecond: RECORDS_PER_SECOND, recordsBurst: RECORDS_BURST, charsPerSecond: RECORD_CHARS_PER_SECOND, charsBurst: RECORD_CHARS_BURST, queueRecords: L.queueRecords, queueChars: L.queueChars }); } - /** @private Take one of `session`'s record tokens and `chars` of its record size budget (R2-3), or neither. @returns {boolean} */ - _recordBudget(session, chars = 0) { - return takeBoth(session, '_recordBucket', RECORDS_PER_SECOND, RECORDS_BURST, '_recordCharsBucket', RECORD_CHARS_PER_SECOND, RECORD_CHARS_BURST, chars); + /** @private The admission queue in front of the record budget (lib/flow-control.js). */ + _makeAdmission() { + const node = this._node; + return new RecordAdmission({ + wait: (session, chars, now) => this._admitWait(session, chars, now), + run: (e) => { + this._spendVerify(e.session, e.chars); + return this._processRecord(e.peerId, e.peerName, e.msg, e.session); + }, + // The door, consulted per frame (MMP §5.8.1), and again for a record that waited: a peer no + // longer admitted (evicted, penalised) has what it queued dropped, counted. + admitted: (e) => { + if (typeof node._penalised === 'function' && node._penalised(e.peerId)) return false; + if (typeof node._floodPenalised === 'function' && node._floodPenalised(e.peerId)) return false; + return typeof node._roomDoor !== 'function' || node._roomDoor(e.peerId).pass === true; + }, + sessionFor: (peerId) => { + const s = node._peers && node._peers.get(peerId) && node._peers.get(peerId).transport; + return s && s.confirmed && !s.closed && !s.legacy && typeof s.trySend === 'function' ? s : null; + }, + cut: (session) => { if (typeof node._penaliseFlood === 'function') node._penaliseFlood(session); }, + fail: (e, err) => { + if (typeof node._refuseFrame === 'function') node._refuseFrame(e.peerId, e.peerName, e.msg, e.session && e.session.kind === 'relay' ? 'relay' : 'lan', err); + }, + metric: (m) => { try { node.emit('metric', m); } catch { /* a sink's failure is not the queue's */ } }, + say: (key, line) => this._sayOnceAMinute(this._audienceSaid, key, (more) => `${line}${more}`), + }); } _markCmbSurfaced(key, msg) { @@ -621,6 +660,15 @@ class FrameHandler { if (typeof this._node._noteSessionRefusal === 'function') this._node._noteSessionRefusal(session, msg.type, 'legacy-attest-frame'); return undefined; + // Flow control (0.14.3, lib/flow-control.js): the peer's record budget, and the records of this + // node's it refused past its queue. A 0.14.2 node ignores both (§7.3, below). + case BUDGET_FRAME: + if (typeof this._node._onPeerBudget === 'function') this._node._onPeerBudget(session, msg); + return undefined; + case REFUSED_FRAME: + if (typeof this._node._onPeerRefused === 'function') this._node._onPeerRefused(session, msg); + return undefined; + case 'cmb-fetch': return this._handleCmbFetch(peerId, peerName, msg, session); @@ -861,15 +909,10 @@ class FrameHandler { if (!md.sig) return refuse('unsigned'); if (typeof md.createdByNodeId !== 'string' || !md.createdByNodeId) return refuse('no-author-node-id'); // The work a record costs is charged before any of it is done (final re-review, Finding 3): the - // session's verification lane, then the (relayer, author) failure window. Dropped unchecked and - // unmarked either way, so a genuine copy from elsewhere is still taken. + // session's verification lane was spent when the record was admitted (_handleMemoryShare), then + // the (relayer, author) failure window, dropped unchecked and unmarked, so a genuine copy from + // elsewhere is still taken. const session = this._sessionOf.get(msg); - if (session && !this._verifyBudget(session, recordChars(cmb))) { - msg._cmbVerified = false; - this._node.emit('metric', { type: 'cmb-over-verify-budget', from: peerName, key: k }); - this._sayOnceAMinute(this._audienceSaid, `${peerId}|verify-budget`, (more) => `CMBs from ${peerName} over its verification budget (${VERIFY_PER_SECOND}/s) — dropped unchecked${more}`); - return true; - } if (typeof this._node._relayMuted === 'function' && this._node._relayMuted(peerId, md.createdByNodeId)) { msg._cmbVerified = false; this._node.emit('metric', { type: 'relayed-signer-muted', kind: 'record', peer: peerId, author: md.createdByNodeId.slice(0, 128) }); @@ -1209,6 +1252,15 @@ class FrameHandler { // own node authored is marked one. if (msg.cmb && msg.cmb.metadata && msg.cmb.metadata.createdByNodeId === session.nodeId) msg._anchor = true; } + // FLOW CONTROL (0.14.3): a session's records are admitted in order, each once both of its lanes + // hold it; one that arrives past the budget, or behind one that waits, is queued until they do, + // and only past the queue's bound refused, its sender told (lib/flow-control.js). + if (session) return this._admission.offer(session, peerId, peerName, msg, recordChars(msg && msg.cmb)); + return this._processRecord(peerId, peerName, msg, session); + } + + /** @private One record, admitted: verified, evaluated and surfaced (or refused on its merits). */ + _processRecord(peerId, peerName, msg, session) { // The session rides beside the frame, never on it: entries are built from the frame and kept. if (session) this._sessionOf.set(msg, session); let pending; @@ -1442,13 +1494,9 @@ class FrameHandler { // A session's new records are evaluated at most RECORDS_PER_SECOND (burst RECORDS_BURST): charged // here, after the signature and the de-duplication and before SVAF encodes anything, which is - // most of what a record costs (security review D, record-flood). Past it the record is dropped - // unmarked, so a later copy is taken. - if (session && !this._recordBudget(session, recordChars(msg.cmb))) { - this._node.emit('metric', { type: 'cmb-over-budget', from: peerName, key: cognitionKey }); - this._sayOnceAMinute(this._audienceSaid, `${peerId}|record-budget`, (more) => `CMBs from ${peerName} over its budget (${RECORDS_PER_SECOND}/s) — dropped unevaluated${more}`); - return; - } + // most of what a record costs (security review D, record-flood). The record was admitted only once + // the lane held it (_handleMemoryShare), and nothing since spent it, so this never overdraws. + if (session) this._spendRecord(session, recordChars(msg.cmb)); // A record signed to this node by its author, verified, fresh, new and within the session's // budget, is accepted for delivery from here on whatever SVAF decides about memory (it surfaces, diff --git a/lib/node.js b/lib/node.js index 67d0e6d0..f28d6d6f 100644 --- a/lib/node.js +++ b/lib/node.js @@ -211,15 +211,20 @@ function inboxChars(m) { /** inbox file -> the SymNode in this process that owns it (see the constructor). */ const INBOX_OWNERS = new Map(); /** - * Records held for a peer's next session after a relay close (R3-4), at most: per peer by count and - * bytes (the pacer's own per-destination bound), and in all (the pacer's queue bound). And the bytes of - * re-offered records waiting in one relay session's pacer queue at once. + * Records held for a peer (R3-4; flow control, 0.14.3: waiting for its record budget, refused and + * waiting for its retry-after, or left by a closed session), at most: per peer by count and size (the + * pacer's own per-destination bounds; characters, as the record budget counts them), and in all (the + * pacer's queue bound). And the bytes and the records waiting in one relay session's pacer queue at once. */ const REDELIVER_PER_PEER = 2048; -const REDELIVER_PER_PEER_BYTES = 8 * 1024 * 1024; +const REDELIVER_PER_PEER_CHARS = 8 * 1024 * 1024; const REDELIVER_MAX = 10_000; const REOFFER_WINDOW_BYTES = 4 * 1024 * 1024; const REOFFER_WINDOW_COUNT = 512; +const { + BUDGET_FRAME, REFUSED_FRAME, HELD_REFUSALS_MAX, HELD_MAX_AGE_MS, SENT_WINDOW_MS, SENT_WINDOW_MAX, UNDELIVERED_LOG_MAX, FLOOD_PENALTY_MS, + recordChars, parseBudgetFrame, parseRefusedFrame, OutboundBudget, +} = require('./flow-control'); /** What start() returns on a running node with nothing queued (the same promise each time). */ const RUNNING = Promise.resolve(); /** A peer that delivered a forged signature is not admitted again for this long (security review D). */ @@ -235,7 +240,7 @@ const KNOWN_FRAME_TYPES = new Set(['cmb', 'cmb-encrypted', 'control-encrypted', 'ping', 'pong', 'error', 'cmb-anchors', 'mood', 'wake-channel', 'peer-info', 'sym-attest-attestation', 'sym-attest-checkpoint', 'sym-attest-witness', 'sym-attest-node-stats', 'attestation', 'checkpoint', 'witness', 'node-stats', 'cmb-fetch', 'cmb-fetch-result', 'role-grant', 'role-revoke', 'role-chain-fetch', 'role-chain', 'role-digest', 'authority-statement', 'authority-digest', - 'authority-fetch', 'authority-set', 'xmesh-insight', 'room-join', 'handshake', + 'authority-fetch', 'authority-set', 'xmesh-insight', 'room-join', 'handshake', 'cmb-budget', 'cmb-refused', 'state-sync', 'message', 'session-confirmed', 'relay-auth', 'relay-peers', 'relay-peer-joined', 'relay-peer-left', 'relay-ping', 'relay-pong', 'relay-reauth', 'relay-error']); /** 1011 replies to relay froms this node holds no session with: a token bucket over all of them. */ @@ -302,6 +307,7 @@ const NOT_SENT = Object.freeze({ SEND_FAILED: 'send-failed', // a transport that says only whether, not why UNSEALABLE: 'unsealable', // not a signed v2.0 record: nothing else travels in Core Secure QUEUE_FULL: 'queue-full', // the relay pacer's queue is full + HELD_FULL: 'held-full', // the records held for that peer are at their bound (flow control) }); /** How each reason reads in the log. */ @@ -312,6 +318,7 @@ const NOT_SENT_SAID = Object.freeze({ [NOT_SENT.SEND_FAILED]: 'send failed', [NOT_SENT.UNSEALABLE]: 'not a signed v2.0 record (only those travel in Core Secure)', [NOT_SENT.QUEUE_FULL]: 'the relay send queue is full', + [NOT_SENT.HELD_FULL]: 'the records held for that peer are at their bound (2048 or 8 Mi characters a peer, 10,000 in all)', }); /** @@ -2338,8 +2345,9 @@ class SymNode extends EventEmitter { for (const [peerId, peer] of this._peers) { // Only a frame a transport took counts: this counted every peer, so a block no peer could take // (too large, a closed socket) was logged as shared with all of them. - const sent = trySend(peer.transport, { type: 'cmb', timestamp: ts, cmb }); - if (sent.ok) shared++; + // Held for the peer's record budget counts as shared: it is written as the budget refills. + const sent = this._sendRecord(peerId, { type: 'cmb', timestamp: ts, cmb }, peer.transport); + if (sent.written || sent.queued) shared++; else this._log(`Not shared with ${peer.name || peerId.slice(0, 8)}: ${NOT_SENT_SAID[sent.reason] || sent.reason}${sent.bytes ? ` (${sent.bytes} bytes)` : ''}`); } @@ -2646,6 +2654,9 @@ class SymNode extends EventEmitter { this._legacy.stop(); if (this._interior) this._interior.close(); + // Records queued past a peer's budget are refused, the peer told while its session is still open, + // so it offers them again to this node's next session (flow control). + try { this._frameHandler._admission.stop(); } catch (err) { this._log(`Stopping the record queue failed: ${err && err.message}`); } // Every session, confirmed or not, ends with the node; a relay session tells its peer. for (const session of [...this._sessions]) { try { session.close('node-stopped'); } catch { /* shutting down */ } @@ -3197,7 +3208,7 @@ class SymNode extends EventEmitter { // Encrypt categories per-peer if shared secret is available (E2E encryption) const baseCmb = entry.cmb || null; - const { dispatched: shared, reason: notSent } = this._dispatchCmb(baseCmb, entry.storedAt, opts.to); + const { dispatched: shared, queued, reason: notSent } = this._dispatchCmb(baseCmb, entry.storedAt, opts.to); // Feed signal to the Layer-6 insight engine, when one is injected if (this._xmesh) this._xmesh.ingestSignal({ @@ -3210,8 +3221,8 @@ class SymNode extends EventEmitter { }); const fanoutDesc = opts.to - ? `target=${opts.to.slice(0, 8)} (${shared ? 'sent' : NOT_SENT_SAID[notSent] || notSent})` - : `${shared}/${this._peers.size} peers`; + ? `target=${opts.to.slice(0, 8)} (${shared ? 'sent' : queued ? 'held for its record budget' : NOT_SENT_SAID[notSent] || notSent})` + : `${shared}/${this._peers.size} peers${queued ? `, ${queued} held for their record budget` : ''}`; this._log(`Remembered: "${content.slice(0, 50)}${content.length > 50 ? '...' : ''}" → ${fanoutDesc}`); // MMP §4.4.4 — the addressed send is the one promise this layer makes, so it is @@ -3242,16 +3253,22 @@ class SymNode extends EventEmitter { // `undelivered` is still sound as written, and is the load-bearing category: // never-dispatched does entail never-delivered, even though the converse // does not hold. + // + // `queued` (flow control, 0.14.3) counts copies held for a peer's record budget: not dispatched + // yet, written as the budget refills, listed in pendingDeliveries() until they are, and said + // undelivered (the 'undelivered' event) if they are given up. A directed send held is not + // undelivered. Object.defineProperty(entry, 'delivery', { value: Object.freeze({ directed: !!opts.to, to: opts.to || null, targets: opts.to ? (this._peers.has(opts.to) ? 1 : 0) : this._peers.size, dispatched: shared, - undelivered: !!opts.to && shared === 0, + queued, + undelivered: !!opts.to && shared === 0 && queued === 0, // Why a directed send was not dispatched (NOT_SENT_SAID's keys): not connected is one // reason of several, and the one this used to report for all of them. - ...(opts.to && shared === 0 ? { reason: notSent } : {}), + ...(opts.to && shared === 0 && queued === 0 ? { reason: notSent } : {}), }), enumerable: false, configurable: true, @@ -3690,7 +3707,9 @@ class SymNode extends EventEmitter { try { cmb = this._mintMessage(content, to); } catch (err) { this._log(`Message to ${String(to).slice(0, 8)} not sent: ${err.message}`); continue; } const peer = this._peers.get(to); if (!peer) continue; - if (trySend(peer.transport, { type: 'cmb', timestamp: Date.now(), cmb }).ok) delivered++; + // Through the peer's held list (flow control): written within its record budget, or held. + const r = this._sendRecord(to, { type: 'cmb', timestamp: Date.now(), cmb }, peer.transport); + if (r.written || r.queued) delivered++; } // A sleeping peer is woken, and the message waits for it as a record signed to it (the retired // `message` frame is never queued). @@ -3885,8 +3904,11 @@ class SymNode extends EventEmitter { // WHY the relay is not connected, and the one-line description that says the fix. relayState: this._relay.state(), relayStatus: this._relay.describe(), - // Records a relay close left unsent, held for their peers' next sessions (pendingDeliveries()). + // Records taken to send and not yet dispatched: held for a peer's record budget or retry-after, + // or left by a closed session (pendingDeliveries()); flowControl says what was queued, refused + // and given up, as a receiver and as a sender (undelivered() lists the last given up). pendingDeliveries: this._redeliverCount || 0, + flowControl: this.flowStatus(), peers: this.peers(), peerCount: this._peers.size, memoryCount: this.memories(), @@ -4217,6 +4239,7 @@ class SymNode extends EventEmitter { _admitSession(session) { const nodeId = session.nodeId; if (this._penalised(nodeId)) { this._refuseAdmission(session, 'delivered a forged signature; not admitted again yet'); return; } + if (this._floodPenalised(nodeId)) { this._refuseAdmission(session, 'kept sending records past this node\'s queue after it was told; not admitted again yet'); return; } // EVERY CONFIRMED SESSION RUNS WITH A BINDING (security review D, binding-squat): its proven key is // held for nodeId while the session lives (the session-scoped table, bounded by the session caps), // and a second key for that nodeId is a conflict. The durable registry takes only EARNED @@ -4331,6 +4354,9 @@ class SymNode extends EventEmitter { * @private */ _greetSession(peer, session, isNew) { + // Flow control (0.14.3): this node's record budget for the session, first, so the peer paces what + // it sends to it (a 0.14.2 peer ignores the frame, §7.3). + if (this._flowSession(session)) session.send(this._frameHandler.flowBudget()); if (!this._lastAnchorSent) this._lastAnchorSent = new Map(); const lastSent = this._lastAnchorSent.get(peer.peerId) || 0; const now = Date.now(); @@ -4354,7 +4380,9 @@ class SymNode extends EventEmitter { announced = true; session.send({ type: 'cmb-anchors', keys: anchors.map((a) => a.cmb.metadata.key) }); let sent = 0; - for (const a of anchors) if (session.send({ type: 'cmb', cmb: a.cmb })) sent++; + // Anchors spend the session's record budget as any record does (at most five: within the burst). + const flow = this._flowSession(session) ? this._outFlow(session) : null; + for (const a of anchors) if (session.send({ type: 'cmb', cmb: a.cmb })) { sent++; if (flow) flow.take(recordChars(a.cmb)); } this._log(`Sent ${sent} anchor CMB(s) to ${peer.name}`); } } else if (isNew) { @@ -4377,13 +4405,19 @@ class SymNode extends EventEmitter { let sent = 0; for (const e of pending) { if (!e || !e.frame || e.key !== session.identityKey || !this._sessionTakes(session, e.frame.type)) continue; - if (session.send(e.frame)) sent++; + // A queued record (a message to a sleeping peer) goes through the peer's held list, paced. + if (e.frame.type === 'cmb' && this._flowSession(session)) { + const r = this._sendRecord(peer.peerId, e.frame, session); + if (r.written || r.queued) sent++; + } else if (session.send(e.frame)) sent++; } this._log(`Delivered ${sent} of ${pending.length} pending frame(s) to ${peer.name}`); this._pendingFrames.delete(peer.peerId); } // Records a relay close left unsent (R3-4), to a session proving the key they were sealed to. this._reofferHeld(peer.peerId, session); + // Refusals of this peer's records owed since its last session closed (flow control). + this._frameHandler._admission.flushFor(peer.peerId); } /** @private A frame from a session: the door first (design D6), then the one guarded dispatch. */ @@ -5037,10 +5071,13 @@ class SymNode extends EventEmitter { } /** - * Fan a CMB out to every peer, or to one peer when `to` is set (MMP §4.4.4). - * @returns {{ dispatched: number, reason: string|null }} `dispatched` counts frames a transport - * accepted (not frames a peer received); `reason` is why the last peer that did not get one did - * not (NOT_SENT_SAID's keys), or null when every target got one. + * Fan a CMB out to every peer, or to one peer when `to` is set (MMP §4.4.4). Each peer's copy goes + * through that peer's held list (_sendRecord): written now when its session's budget holds it, else + * held and written as the budget refills. + * @returns {{ dispatched: number, queued: number, reason: string|null }} `dispatched` counts frames a + * session took within its peer's budget (not frames a peer received); `queued`, copies held for the + * budget (listed in pendingDeliveries() until written); `reason` is why the last peer that got + * neither did not (NOT_SENT_SAID's keys), or null when every target got one or the other. * @private */ _dispatchCmb(baseCmb, timestamp, to) { @@ -5062,22 +5099,17 @@ class SymNode extends EventEmitter { } let shared = 0; + let queued = 0; for (const [peerId, peer] of targets) { // One sealed frame per peer session (design D4): each session has its own keys. The record's // binding — directed or room-bound — is its signed, AAD-bound `metadata.to` (§8.8.4), never a // frame flag; the session refuses a record that is not a signed v2.0 record. - const frame = { type: 'cmb', timestamp, cmb: baseCmb }; - const t = peer.transport; - // On a relay session the frame waits in the pacer; a `meta` rides with it, so a record the pacer - // never wrote before the connection closed is held for the peer's next session (R3-4). - const meta = t && t.kind === 'relay' && typeof t.identityKey === 'string' - ? { redeliver: true, to: peerId, key: t.identityKey, sessionId: t.sessionId, frame, recordKey: recordKey(baseCmb), since: Date.now(), attempts: 1, held: false, offered: false, bytes: 0 } - : null; - const sent = meta ? t.trySend(frame, meta) : trySend(t, frame); + const sent = this._sendRecord(peerId, { type: 'cmb', timestamp, cmb: baseCmb }, peer.transport); // A transport refuses a frame when the socket is closed, the relay is not open, the write // failed or the frame is over MAX_FRAME_SIZE. Counting those as dispatched made a stale peer // read as reached, and reporting them all as "not connected" hid a frame no peer could take. - if (sent.ok) { shared++; continue; } + if (sent.written) { shared++; continue; } + if (sent.queued) { queued++; continue; } reason = sent.reason; if (sent.reason === SEND_FAILURE.TOO_LARGE) { this._log(`CMB ${String(recordKey(baseCmb) || '').slice(0, 16)} not sent to ${peer.name || peerId.slice(0, 8)}: its frame is ${sent.bytes} bytes, over the ${MAX_FRAME_SIZE}-byte bound`); @@ -5085,26 +5117,97 @@ class SymNode extends EventEmitter { } } - return { dispatched: shared, reason }; + return { dispatched: shared, queued, reason }; } - // ── Records the relay pacer never wrote (R3-4) ───────────── + // ── Records to each peer: paced, held and offered again (R3-4; flow control, 0.14.3) ────────── + // + // EVERY RECORD TO A PEER GOES THROUGH THAT PEER'S HELD LIST, oldest first. It is written to the + // peer's session only within the record budget that peer advertised for it (`cmb-budget`; a peer + // that advertises nothing — 0.14.2 and older — gets the 0.14.2 budget with a margin, LEGACY_BUDGET) + // and, on a relay session, while the pacer has room. What fits is written at once; the rest waits + // and is written as the budget refills. A record counts as dispatched only when it is written. // - // `dispatched` counts records a session took. On a relay session a record then waits in the pacer - // (20 frames a second), and the pacer was simply emptied when the connection closed: 260 directed - // records reported dispatched, 227 lost after one drop. Now what the pacer still holds when the - // connection closes comes back here, is HELD for that peer — for the identity key it was sealed - // to — and is offered again, sealed afresh, to the next session that proves that key (over the - // relay or the LAN). It is reported as not delivered until it is written to a socket: - // pendingDeliveries() lists it, status().pendingDeliveries counts it, and metrics say each step - // ('cmb-requeued', 'cmb-redelivered', and 'cmb-undelivered' when it is dropped: the bound below, or - // the node stopping). A receiver surfaces a record once for the life of its store (the delivery - // ledger), so one offered twice is not delivered twice. + // Until 0.14.3 a record was written at once whatever the receiver could take, and the receiver + // dropped what was past its budget, unevaluated, while this node reported it dispatched: 49 directed + // messages in a burst arrived as 38; 12 of 200 KB as 7; 120 records re-offered after a relay drop + // as 37 (this node said 115 redelivered). The receiver now queues what is past its budget and + // refuses only past its queue, naming the records (`cmb-refused`): those come back here, are held + // again in their place, and are offered again after the retry-after it gave; after + // HELD_REFUSALS_MAX refusals, or once a record is HELD_MAX_AGE_MS old by its signed timestamp (past + // that a receiver refuses a directed record as a replay), it is given up and said undelivered. // - // THE RESIDUAL: a frame written to the socket and lost after that (in the kernel, in the relay, - // on the relay's way to the peer) is still lost and still reads as dispatched. Only an end-to-end - // receipt would close that, and that is protocol work. The held list is process memory: a node - // that stops or crashes drops it (the record stays in its store). + // On a relay session a record written waits in the pacer (20 frames a second), and is written to + // the socket later: it stays on the list (`offered`) until the socket's write callback says so, and + // what the pacer still holds when the connection or the session closes comes back here, held for + // that peer — for the identity key it was sealed to — and offered again, sealed afresh, to the next + // session that proves that key (over the relay or the LAN). It is reported as not delivered until + // then: pendingDeliveries() lists it, status().pendingDeliveries counts it, and metrics say each + // step ('cmb-requeued' with why, 'cmb-redelivered' when a held record is written, 'cmb-undelivered' + // and the 'undelivered' event when one is given up; undelivered() lists the last of those). A + // receiver surfaces a record once for the life of its store (the delivery ledger), so one offered + // twice is not delivered twice. + // + // THE RESIDUAL: a frame written to a socket and lost after that (in the kernel, in the relay, on the + // relay's way to the peer, or in a LAN socket's buffer when it closes) is still lost and still reads + // as dispatched. Only an end-to-end receipt would close that, and that is protocol work. The held + // list is process memory: a node that stops or crashes drops it (the record stays in its store). + + /** @private Whether records to `s` are flow-controlled: a Core Secure session that proved a key. */ + _flowSession(s) { + return !!s && typeof s.trySend === 'function' && typeof s.identityKey === 'string' && !!s.identityKey && !s.legacy; + } + + /** @private `session`'s outbound record budget, as its receiver keeps it (lib/flow-control.js). */ + _outFlow(session) { + return session._outFlow || (session._outFlow = new OutboundBudget(Date.now())); + } + + /** @private The flow-control counters status() reports. */ + _flowCounters() { + return this._flowStats || (this._flowStats = { written: 0, paced: 0, refusedByPeers: 0, refusedUnmatched: 0, undelivered: 0, budgetsHeard: 0, cut: 0 }); + } + + /** + * @private Send one record frame to one peer through its held list: written now when nothing of the + * peer's waits ahead of it and its session's budget (and a relay pacer's room) holds it; otherwise + * held, and written as the budget refills. A record the session refused outright (too large, not + * addressed to it, the transport down) is not held: it is reported as before. + * @returns {{ written?: true, queued?: true, reason?: string, bytes?: number }} + */ + _sendRecord(peerId, frame, session) { + const s = session || (this._peers.get(peerId) || {}).transport; + if (!s) return { reason: SEND_FAILURE.NOT_CONNECTED }; + if (!this._flowSession(s) || !this._running) { + // A transport no handshake proved a key for (an embedder's, a test's), or a node not running + // (nothing would write a held record later): written at once, as before. + const sent = trySend(s, frame); + return sent.ok ? { written: true } : { reason: sent.reason, bytes: sent.bytes }; + } + if (!s.confirmed || s.closed) return { reason: SEND_FAILURE.NOT_CONNECTED }; + const cmb = frame && frame.cmb; + const md = cmb && cmb.metadata; + const now = Date.now(); + const m = { + redeliver: true, to: peerId, key: s.identityKey, frame, recordKey: recordKey(cmb), + assertionId: md && typeof md.assertionId === 'string' ? md.assertionId : null, + chars: recordChars(cmb), bytes: 0, since: now, + signedAt: md && Number.isFinite(md.createdTimestamp) ? md.createdTimestamp : now, + attempts: 0, refusals: 0, notBefore: 0, held: false, offered: false, reported: false, written: false, sessionId: null, + }; + if (!this._holdRecord(m)) return { reason: NOT_SENT.HELD_FULL }; + this._reofferHeld(peerId, s); + if (m.written) return { written: true }; + if (!m.held || m.attempts > 0) { + // The session refused it (as before this was a send it did not take): not held, said by the caller. + this._unhold(m); + return { reason: m.failed || NOT_SENT.SEND_FAILED, ...(m.failedBytes ? { bytes: m.failedBytes } : {}) }; + } + m.reported = true; + this._flowCounters().paced++; + this._metricSafe({ type: 'cmb-requeued', to: peerId, key: m.recordKey, reason: 'paced' }); + return { queued: true }; + } /** @private Records the pacer handed back on a close: held for each peer's next session. */ _holdUnflushed(items) { @@ -5115,7 +5218,7 @@ class SymNode extends EventEmitter { const m = it && it.meta; if (!m || !m.redeliver) continue; if (m.held) this._releaseHeld(m, 'node-stopped'); - else this._metricSafe({ type: 'cmb-undelivered', to: m.to, key: m.recordKey, reason: 'node-stopped' }); + else this._reportUndelivered(m, 'node-stopped'); } return; } @@ -5125,8 +5228,11 @@ class SymNode extends EventEmitter { const m = it && it.meta; if (!m || !m.redeliver) continue; m.offered = false; + m.refusedEarly = false; // held again either way; its retry-after (notBefore) stands if (Number.isFinite(it.bytes)) m.bytes = it.bytes; - if (!m.held && !this._holdRecord(m)) continue; + if (!m.held && !this._holdRecord(m)) { this._reportUndelivered(m, 'held-full'); continue; } + m.reported = true; + this._metricSafe({ type: 'cmb-requeued', to: m.to, key: m.recordKey, reason: 'unflushed' }); held++; peers.add(m.to); } @@ -5141,152 +5247,379 @@ class SymNode extends EventEmitter { try { this.emit('metric', m); } catch { /* a bad sink never stops the bookkeeping */ } } - /** @private Hold one record for its peer, within the bounds. @returns {boolean} held */ + /** + * @private Hold one record for its peer, in the order records were first sent, within the bounds: per + * peer by count and size, and in all. A record that does not fit is not held — a new one is refused + * (its send says so), one coming back is said undelivered — and nothing held is pushed out for it. + * @returns {boolean} held + */ _holdRecord(m) { + if (!Number.isFinite(m.chars)) m.chars = recordChars(m.frame && m.frame.cmb); + if (!Number.isFinite(m.signedAt)) { + const ts = m.frame && m.frame.cmb && m.frame.cmb.metadata ? m.frame.cmb.metadata.createdTimestamp : undefined; + m.signedAt = Number.isFinite(ts) ? ts : Date.now(); + } + if (!Number.isFinite(m.refusals)) m.refusals = 0; + if (!Number.isFinite(m.notBefore)) m.notBefore = 0; if (!this._redeliver) this._redeliver = new Map(); let list = this._redeliver.get(m.to); - if (!list) { list = []; this._redeliver.set(m.to, list); } + const count = list ? list.items.length : 0; + if (count >= REDELIVER_PER_PEER || (count > 0 && list.chars + m.chars > REDELIVER_PER_PEER_CHARS) || (this._redeliverCount || 0) >= REDELIVER_MAX) { + try { this._sayOncePerMinute('redeliver-full', `UNDELIVERED: the records held for a peer are at the bound (${REDELIVER_PER_PEER} or ${REDELIVER_PER_PEER_CHARS} characters a peer, ${REDELIVER_MAX} in all): a record past it is not sent`); } catch { /* said or not, refused */ } + return false; + } + if (!list) { list = { items: [], chars: 0 }; this._redeliver.set(m.to, list); } m.held = true; - list.push(m); - // Oldest first: a record dispatched earlier can come back later (its session ended later). - if (list.length > 1 && list[list.length - 2].since > m.since) list.sort((x, y) => x.since - y.since); + // Oldest first: a record sent earlier can come back later (refused, or its session ended later). + let i = list.items.length; + while (i > 0 && list.items[i - 1].since > m.since) i--; + list.items.splice(i, 0, m); + list.chars += m.chars; this._redeliverCount = (this._redeliverCount || 0) + 1; - this._metricSafe({ type: 'cmb-requeued', to: m.to, key: m.recordKey }); - // The bounds: per peer by count and bytes, and in all; the oldest held record goes first. - const bytes = () => list.reduce((n, x) => n + (x.bytes || 0), 0); - while (list.length > REDELIVER_PER_PEER || (list.length > 1 && bytes() > REDELIVER_PER_PEER_BYTES)) this._releaseHeld(list[0], 'redelivery-overflow'); - while (this._redeliverCount > REDELIVER_MAX) { - const oldest = [...this._redeliver.values()].filter((l) => l.length).sort((x, y) => x[0].since - y[0].since)[0]; - if (!oldest) break; - this._releaseHeld(oldest[0], 'redelivery-overflow'); - } - return m.held; + return true; } - /** - * @private A held record leaves the list: written to a socket ('redelivered'), or dropped (any other - * reason: said as not delivered). - */ - _releaseHeld(m, outcome) { - if (!m || !m.held) return; + /** @private Take a record off its peer's held list, saying nothing. @returns {boolean} it was held */ + _unhold(m) { + if (!m || !m.held) return false; m.held = false; m.offered = false; const list = this._redeliver && this._redeliver.get(m.to); if (list) { - const i = list.indexOf(m); - if (i !== -1) { list.splice(i, 1); this._redeliverCount--; } - if (!list.length) this._redeliver.delete(m.to); + const i = list.items.indexOf(m); + if (i !== -1) { list.items.splice(i, 1); list.chars -= m.chars; this._redeliverCount--; } + if (!list.items.length) this._redeliver.delete(m.to); } + return true; + } + + /** + * @private A held record leaves the list: written ('sent' in its first pass, said nothing more; + * 'redelivered' once it had been held), or given up (any other outcome: said undelivered). + */ + _releaseHeld(m, outcome) { + if (!this._unhold(m)) return; + if (outcome === 'sent') return; if (outcome === 'redelivered') { this._metricSafe({ type: 'cmb-redelivered', to: m.to, key: m.recordKey, attempts: m.attempts }); return; } - if (outcome === 'redelivery-overflow') { - try { this._sayOncePerMinute('redeliver-overflow', `UNDELIVERED: held records over the bound (${REDELIVER_PER_PEER} or ${REDELIVER_PER_PEER_BYTES} bytes a peer, ${REDELIVER_MAX} in all): the oldest are dropped, not sent`); } catch { /* said or not, dropped */ } + this._reportUndelivered(m, outcome); + } + + /** @private A record this node will not send again: counted, listed (undelivered()), said, and raised. */ + _reportUndelivered(m, reason) { + this._flowCounters().undelivered++; + const item = Object.freeze({ to: m.to, key: m.recordKey || null, assertionId: m.assertionId || null, reason, attempts: m.attempts || 0, refusals: m.refusals || 0, since: m.since || null, at: Date.now() }); + if (!this._undeliveredLog) this._undeliveredLog = []; + this._undeliveredLog.push(item); + if (this._undeliveredLog.length > UNDELIVERED_LOG_MAX) this._undeliveredLog.shift(); + this._metricSafe({ type: 'cmb-undelivered', to: m.to, key: m.recordKey, reason }); + try { this._sayOncePerMinute(`undelivered|${reason}`, `UNDELIVERED: record ${String(m.recordKey || m.assertionId || '').slice(0, 16)} to ${String(m.to).slice(0, 8)} given up (${reason}); it stays in this node's store (undelivered())`); } catch { /* said or not, counted */ } + // The event a host shows: a send this node had taken and now will not make. + try { this.emit('undelivered', item); } catch (err) { try { this._log(`An 'undelivered' listener threw: ${err && err.message}`); } catch { /* */ } } + } + + /** + * @private A record was written to its session within its peer's budget (a LAN session), or the relay + * socket wrote it: dispatched. It is remembered SENT_WINDOW_MS, so a refusal naming it brings it back. + */ + _recordWritten(m) { + this._releaseHeld(m, m.reported ? 'redelivered' : 'sent'); + this._flowCounters().written++; + if (!m.assertionId) return; + if (!this._sentWindow) this._sentWindow = new Map(); + const k = `${m.to}|${m.assertionId}`; + m.sentAt = Date.now(); + this._sentWindow.delete(k); + this._sentWindow.set(k, m); + this._pruneSentWindow(m.sentAt); + } + + /** @private The records written that a refusal may still name: the last SENT_WINDOW_MS, at most SENT_WINDOW_MAX. */ + _pruneSentWindow(now = Date.now()) { + const w = this._sentWindow; + if (!w) return; + for (const [k, m] of w) { + if (w.size <= SENT_WINDOW_MAX && now - m.sentAt < SENT_WINDOW_MS) break; + w.delete(k); } - this._metricSafe({ type: 'cmb-undelivered', to: m.to, key: m.recordKey, reason: outcome }); } - /** @private The pacer wrote a frame sent with a meta: a held record is delivered as far as this node can tell. */ + /** @private The pacer wrote a frame sent with a meta: the record is dispatched as far as this node can tell. */ _redeliveryFlushed(m) { - if (!m || !m.held) return; + if (!m || !m.held || !m.offered) return; const to = m.to; - this._releaseHeld(m, 'redelivered'); + if (m.refusedEarly) { + // The peer refused it before this node heard the socket had written it: held again, as a refusal is. + m.offered = false; + m.refusedEarly = false; + this._metricSafe({ type: 'cmb-requeued', to, key: m.recordKey, reason: 'refused' }); + this._scheduleReoffer(to, Math.max(0, m.notBefore - Date.now())); + return; + } + this._recordWritten(m); // The next held records for that peer go once there is room in the pacer. if (this._redeliver && this._redeliver.has(to)) this._scheduleReoffer(to); } /** - * @private Re-offer `nodeId`'s held records soon: next turn, or after `delayMs` (a pass that found no - * room in the pacer and has nothing of its own waiting there to re-arm it). One pending per peer. + * @private Offer `nodeId`'s held records soon: next turn, or after `delayMs` (the budget refilling, a + * retry-after, a pass that found no room in the pacer). One pending per peer, the earliest kept. */ _scheduleReoffer(nodeId, delayMs = 0) { if (!this._running) return; if (!this._reofferSoon) this._reofferSoon = new Map(); - if (this._reofferSoon.has(nodeId)) return; + const at = Date.now() + Math.max(0, delayMs); + const pending = this._reofferSoon.get(nodeId); + if (pending) { + if (pending.at <= at) return; + clearTimeout(pending.t); clearImmediate(pending.t); + } const run = () => { this._reofferSoon.delete(nodeId); try { this._reofferHeld(nodeId); } catch (err) { this._log(`Re-offering held records failed: ${err && err.message}`); } }; + let t; if (delayMs > 0) { - const t = setTimeout(run, delayMs); + t = setTimeout(run, delayMs); if (t.unref) t.unref(); - this._reofferSoon.set(nodeId, t); } else { - this._reofferSoon.set(nodeId, setImmediate(run)); + t = setImmediate(run); } + this._reofferSoon.set(nodeId, { t, at }); } /** - * @private Offer `nodeId`'s held records to `session` (or the peer's current transport): only to a - * confirmed session proving the key each was sealed to, sealed afresh, oldest first. On a relay - * session a record stays held until the pacer writes it, and at most REOFFER_WINDOW_BYTES of them - * wait in the pacer at once (the pacer refuses past its own bound, and a refused sealed frame ends - * the session); on a LAN session it is written at once. + * @private Write `nodeId`'s held records to `session` (or the peer's current transport), oldest first: + * only to a confirmed session proving the key each was sealed to, sealed afresh, each once its + * session's budget holds it (and a refused one once its retry-after has passed). On a relay session + * a record stays held until the pacer writes it, and at most REOFFER_WINDOW_BYTES or + * REOFFER_WINDOW_COUNT of them wait in the pacer at once (the pacer refuses past its own bound, and a + * refused sealed frame ends the session); on a LAN session it is dispatched once written. The pass + * stops at the first record that has to wait, and comes back when it may go. */ _reofferHeld(nodeId, session) { if (!this._running) return; const list = this._redeliver && this._redeliver.get(nodeId); - if (!list || !list.length) return; + if (!list || !list.items.length) return; const s = session || (this._peers.get(nodeId) || {}).transport; - if (!s || s.closed || !s.confirmed || typeof s.trySend !== 'function') return; + if (!this._flowSession(s) || s.closed || !s.confirmed) return; // A relay client session the server has not yet shown it took (it waits to supersede the old one) // is not offered them: if its finish was lost, what it carried is lost with it. It is offered them // once it supersedes (_completeSupersede), and the old one meanwhile is the peer's. if (s._supersedes) return; const relay = s.kind === 'relay'; const room = (bytes) => !relay || !s.transport || typeof s.transport.hasRoom !== 'function' || s.transport.hasRoom(bytes); + const flow = this._outFlow(s); + const now = Date.now(); + let again = 0; let offered = 0; - let waiting = list.filter((m) => m.offered).length; + let waiting = 0; + if (relay) for (const m of list.items) if (m.offered) waiting++; let stalled = false; - for (const m of [...list]) { + for (const m of [...list.items]) { if (!m.held || m.offered || m.key !== s.identityKey) continue; - if (relay && (waiting >= REOFFER_WINDOW_COUNT || (s.pendingBytes() + (m.bytes || 0) > REOFFER_WINDOW_BYTES && s.pendingBytes() > 0) || !room(m.bytes || 0))) { stalled = true; break; } + if (now - m.signedAt > HELD_MAX_AGE_MS) { this._releaseHeld(m, 'expired'); continue; } + if (m.notBefore > now) { again = m.notBefore - now; break; } + const wait = flow.wait(m.chars, now); + if (wait > 0) { again = wait; break; } + // What the sealed frame will weigh in the pacer, until the pacer has said (a record's text, its + // JSON and the AEAD's base64url). + const bytes = m.bytes || Math.ceil(m.chars * 1.4) + 1024; + if (relay && (waiting >= REOFFER_WINDOW_COUNT || (s.pendingBytes() + bytes > REOFFER_WINDOW_BYTES && s.pendingBytes() > 0) || !room(bytes))) { stalled = true; break; } m.attempts++; if (relay) m.sessionId = s.sessionId; const r = relay ? s.trySend(m.frame, m) : s.trySend(m.frame); if (!r || !r.ok) { - const reason = r && r.reason; + const reason = (r && r.reason) || NOT_SENT.SEND_FAILED; + m.failed = reason; + m.failedBytes = r && r.bytes; // A record this session can never take (its audience, too large) is dropped; any other // refusal leaves it held for the next session. - if (reason === 'not-addressed' || reason === 'unsealable' || reason === SEND_FAILURE.TOO_LARGE) this._releaseHeld(m, `redelivery-${reason}`); + if (reason === 'not-addressed' || reason === 'unsealable' || reason === SEND_FAILURE.TOO_LARGE) { + if (m.reported) this._releaseHeld(m, `redelivery-${reason}`); else this._unhold(m); + } if (s.closed) break; continue; } - offered++; - if (relay) { m.offered = true; waiting++; } else this._releaseHeld(m, 'redelivered'); + flow.take(m.chars, now); + m.written = true; + if (m.reported) offered++; + if (relay) { m.offered = true; waiting++; } else this._recordWritten(m); } - if (offered) this._log(`Re-offered ${offered} held record(s) to ${s.name || nodeId.slice(0, 8)} on a new ${s.kind} session`); + if (offered) this._log(`Wrote ${offered} held record(s) to ${s.name || nodeId.slice(0, 8)} (${s.kind} session, within its record budget)`); + if (again > 0) this._scheduleReoffer(nodeId, again); // A pass the pacer's room stopped, with none of these records waiting in it (whose flush would // re-arm the next pass), tries again shortly: the pacer drains at its own rate. - if (stalled && waiting === 0) this._scheduleReoffer(nodeId, 250); + else if (stalled && waiting === 0) this._scheduleReoffer(nodeId, 250); + } + + /** @private Held records past HELD_MAX_AGE_MS are given up, and the sent window pruned (the heartbeat). */ + _sweepHeld(now = Date.now()) { + if (this._redeliver) { + for (const list of [...this._redeliver.values()]) { + for (const m of [...list.items]) if (!m.offered && now - m.signedAt > HELD_MAX_AGE_MS) this._releaseHeld(m, 'expired'); + } + } + this._pruneSentWindow(now); + } + + /** + * @private A peer told this node the record budget it keeps for this session (`cmb-budget`): records + * to it on this session are paced to it from now on. + */ + _onPeerBudget(session, frame) { + const b = parseBudgetFrame(frame); + if (!b) { this._noteSessionRefusal(session, BUDGET_FRAME, 'malformed'); return; } + const flow = this._outFlow(session); + if (!flow.advertised) this._flowCounters().budgetsHeard++; + flow.apply(b, Date.now()); + this._metricSafe({ type: 'peer-budget', peer: session.nodeId, ...b }); + if (this._redeliver && this._redeliver.has(session.nodeId)) this._scheduleReoffer(session.nodeId); + } + + /** + * @private A peer refused records of this node's past its queue (`cmb-refused`): nothing more goes on + * that session until the retry-after, and each record it names that this node wrote in the last + * SENT_WINDOW_MS goes back on the held list, in its place, to be offered after it — to that peer + * only (a room record other peers took is not sent to them again). A record refused more than + * HELD_REFUSALS_MAX times is given up and said undelivered. + */ + _onPeerRefused(session, frame) { + const r = parseRefusedFrame(frame); + if (!r) { this._noteSessionRefusal(session, REFUSED_FRAME, 'malformed'); return; } + const now = Date.now(); + const peerId = session.nodeId; + // The session the notice came on, and the one this node now writes that peer's records on. + this._outFlow(session).backOff(r.retryAfterMs, now); + const current = (this._peers.get(peerId) || {}).transport; + if (current && current !== session && this._flowSession(current)) this._outFlow(current).backOff(r.retryAfterMs, now); + const counters = this._flowCounters(); + let matched = 0; + // A record still marked as waiting in the relay pacer (its write callback not yet seen) may be + // refused already: it is held again when the callback comes (_redeliveryFlushed). + const inPacer = new Map(); + const list = this._redeliver && this._redeliver.get(peerId); + if (list) for (const m of list.items) if (m.offered && m.assertionId) inPacer.set(m.assertionId, m); + for (const id of r.ids) { + const k = `${peerId}|${id}`; + const early = inPacer.get(id); + if (early && !early.refusedEarly) { + matched++; + early.refusals++; + if (early.refusals > HELD_REFUSALS_MAX) { this._releaseHeld(early, 'refused'); continue; } + early.refusedEarly = true; + early.reported = true; + early.notBefore = now + r.retryAfterMs; + continue; + } + const m = this._sentWindow && this._sentWindow.get(k); + if (!m) continue; + this._sentWindow.delete(k); + matched++; + m.refusals++; + if (m.refusals > HELD_REFUSALS_MAX) { this._reportUndelivered(m, 'refused'); continue; } + m.notBefore = now + r.retryAfterMs; + m.offered = false; + m.written = false; + m.reported = true; + if (!this._holdRecord(m)) { this._reportUndelivered(m, 'held-full'); continue; } + this._metricSafe({ type: 'cmb-requeued', to: peerId, key: m.recordKey, reason: 'refused' }); + } + counters.refusedByPeers += matched; + this._metricSafe({ type: 'cmb-refused-by-peer', peer: peerId, count: r.ids.length, matched, retryAfterMs: r.retryAfterMs }); + if (matched < r.ids.length) { + // Not one this node wrote to that peer in the last minute (older, or never this node's): it may + // not have arrived, and nothing here can send it again. Counted and said, nothing more. + counters.refusedUnmatched += r.ids.length - matched; + this._metricSafe({ type: 'cmb-refused-unmatched', peer: peerId, count: r.ids.length - matched }); + } + this._sayOncePerMinute(`refused-by|${peerId}`, `${session.name || peerId.slice(0, 8)} refused ${r.ids.length} record(s) past its queue (${matched} held again here): offered again in ${Math.round(r.retryAfterMs / 1000)} s`); + this._scheduleReoffer(peerId, r.retryAfterMs); + } + + /** + * @private A session that kept sending records past this node's queue after it was told to retry + * (lib/flow-control.js): closed, and its peer not admitted again for FLOOD_PENALTY_MS, as a forgery + * is (an honest sender paces to the budget it was told and never gets here). + */ + _penaliseFlood(session) { + if (!session || session.closed || typeof session.close !== 'function') return false; + const nodeId = session.nodeId; + if (!this._floodPenalty) this._floodPenalty = new Map(); + this._floodPenalty.delete(nodeId); + if (this._floodPenalty.size >= GOSSIP_MAX_PEERS) this._floodPenalty.delete(this._floodPenalty.keys().next().value); + this._floodPenalty.set(nodeId, Date.now() + FLOOD_PENALTY_MS); + this._flowCounters().cut++; + this._metricSafe({ type: 'record-flood-cut', peer: nodeId }); + this._sayOncePerMinute(`flood|${nodeId}`, `[sym-security] ${session.name || String(nodeId).slice(0, 8)} kept sending records past this node's queue after it was told to retry later: session closed, not admitted again for ${FLOOD_PENALTY_MS / 1000} s`); + session.close('record-flood'); + return true; + } + + /** @private Whether `nodeId` is inside a record-flood penalty (and drop it when it has run out). */ + _floodPenalised(nodeId) { + const until = this._floodPenalty && this._floodPenalty.get(nodeId); + if (!until) return false; + if (Date.now() < until) return true; + this._floodPenalty.delete(nodeId); + return false; } /** @private Every held record is dropped (the node stopping): said, and counted as not delivered. */ _dropRedelivery(reason) { if (this._reofferSoon) { - for (const t of this._reofferSoon.values()) { try { clearTimeout(t); clearImmediate(t); } catch { /* */ } } + for (const p of this._reofferSoon.values()) { try { clearTimeout(p.t); clearImmediate(p.t); } catch { /* */ } } this._reofferSoon.clear(); } + if (this._sentWindow) this._sentWindow.clear(); if (!this._redeliver || !this._redeliver.size) return; let n = 0; - for (const list of [...this._redeliver.values()]) for (const m of [...list]) { this._releaseHeld(m, reason); n++; } + for (const list of [...this._redeliver.values()]) for (const m of [...list.items]) { this._releaseHeld(m, reason); n++; } this._redeliver.clear(); this._redeliverCount = 0; if (n) this._log(`UNDELIVERED: ${n} held record(s) dropped (${reason}); they stay in this node's store`); } /** - * Records this node dispatched over a relay session that closed before its pacer sent them, held - * for each peer's next session: NOT delivered until written to one (see above). Oldest first. - * @returns {Array<{ to: string, key: string, since: number, attempts: number, offered: boolean }>} + * Records this node has taken to send and not yet dispatched, held for each peer: waiting for the + * peer's record budget (`waiting`), refused by the peer and waiting for its retry-after + * (`refused`), written to a relay pacer and not yet to the socket (`written`), or left by a session + * that closed. NOT delivered until written (see above). Oldest first. + * @returns {Array<{ to: string, key: string, since: number, attempts: number, offered: boolean, state: string, refusals: number }>} */ pendingDeliveries() { const out = []; - if (this._redeliver) for (const list of this._redeliver.values()) for (const m of list) out.push({ to: m.to, key: m.recordKey, since: m.since, attempts: m.attempts, offered: !!m.offered }); + const now = Date.now(); + if (this._redeliver) { + for (const list of this._redeliver.values()) { + for (const m of list.items) { + out.push({ to: m.to, key: m.recordKey, since: m.since, attempts: m.attempts, offered: !!m.offered, state: m.offered ? 'written' : (m.notBefore > now ? 'refused' : 'waiting'), refusals: m.refusals || 0 }); + } + } + } return out.sort((a, b) => a.since - b.since); } + /** + * The last records (at most 256) this node had taken to send and gave up: refused by the peer more + * than HELD_REFUSALS_MAX times, held past HELD_MAX_AGE_MS, past the held list's bound, or dropped + * when the node stopped. Each is also raised as the 'undelivered' event. + * @returns {Array<{ to: string, key: string|null, assertionId: string|null, reason: string, attempts: number, refusals: number, since: number|null, at: number }>} + */ + undelivered() { + return [...(this._undeliveredLog || [])]; + } + + /** Flow control, as status() reports it: what this node queued and refused as a receiver, and what it holds and gave up as a sender. */ + flowStatus() { + return { + receiver: this._frameHandler && this._frameHandler._admission ? this._frameHandler._admission.status() : null, + sender: { held: this._redeliverCount || 0, sentWindow: this._sentWindow ? this._sentWindow.size : 0, ...this._flowCounters() }, + }; + } + /** * Deliver the record of a send that minted nothing (collapsed onto HEAD, or already stored) to * its one addressed peer, and attach the same `delivery` result a fresh send carries, so the @@ -5296,13 +5629,14 @@ class SymNode extends EventEmitter { */ _dispatchExisting(result, key, to) { const cmb = result.cmb || null; - const { dispatched: shared, reason } = cmb ? this._dispatchCmb(cmb, Date.now(), to) : { dispatched: 0, reason: NOT_SENT.SEND_FAILED }; + const { dispatched: shared, queued = 0, reason } = cmb ? this._dispatchCmb(cmb, Date.now(), to) : { dispatched: 0, reason: NOT_SENT.SEND_FAILED }; + const undelivered = shared === 0 && queued === 0; Object.defineProperty(result, 'delivery', { - value: Object.freeze({ directed: true, to, targets: this._peers.has(to) ? 1 : 0, dispatched: shared, undelivered: shared === 0, ...(shared === 0 ? { reason } : {}) }), + value: Object.freeze({ directed: true, to, targets: this._peers.has(to) ? 1 : 0, dispatched: shared, queued, undelivered, ...(undelivered ? { reason } : {}) }), enumerable: false, configurable: true, }); - if (shared === 0) { + if (undelivered) { this._log(`UNDELIVERED (directed): ${to.slice(0, 8)} ${NOT_SENT_SAID[reason] || reason} — record ${String(key).slice(0, 16)} NOT sent`); this.emit('metric', { type: 'cmb-undelivered', to, key, reason }); } @@ -5314,7 +5648,7 @@ class SymNode extends EventEmitter { */ _markUndelivered(result, key, to, reason) { Object.defineProperty(result, 'delivery', { - value: Object.freeze({ directed: true, to, targets: this._peers.has(to) ? 1 : 0, dispatched: 0, undelivered: true, reason }), + value: Object.freeze({ directed: true, to, targets: this._peers.has(to) ? 1 : 0, dispatched: 0, queued: 0, undelivered: true, reason }), enumerable: false, configurable: true, }); @@ -5349,6 +5683,8 @@ class SymNode extends EventEmitter { _checkHeartbeats() { const now = Date.now(); + // Held records past their age are given up; the sent window is pruned (flow control). + try { this._sweepHeld(now); } catch (err) { this._log(`Sweeping held records failed: ${err && err.message}`); } // Per session (§5.4): every live path is checked, so a degraded secondary is found and closed. for (const session of [...this._sessions]) { if (!session.confirmed) continue; diff --git a/tests/core-secure-final-review.test.js b/tests/core-secure-final-review.test.js index a75f2eb9..2cc68b3a 100644 --- a/tests/core-secure-final-review.test.js +++ b/tests/core-secure-final-review.test.js @@ -108,7 +108,7 @@ describe('C: the interior read side is scoped to the mind\'s mission (Finding 6) }); describe('3: relayed forgeries cost bounded work, and nobody is blamed (Finding 3)', () => { - it('Q1: 400 forged 200 KiB records relayed in another\'s name are mostly dropped before any work, with bounded logs and decisions', async () => { + it('Q1: 400 forged 200 KiB records relayed in another\'s name: most wait or are refused before any work, with bounded logs and decisions', async () => { const b = mk('q1', {}); try { await b.start(); @@ -126,7 +126,9 @@ describe('3: relayed forgeries cost bounded work, and nobody is blamed (Finding } assert.strictEqual(sM.closed, false, 'the relayer is not blamed'); assert.ok((metrics['relayed-signature-unverified'] || 0) <= 8, `verified and failed at most 8: ${metrics['relayed-signature-unverified']}`); - assert.ok((metrics['relayed-signer-muted'] || 0) + (metrics['cmb-over-verify-budget'] || 0) >= 380, 'the rest dropped before any work'); + // Past the pre-verification lane a record waits in the session's queue (flow control, 0.14.3: it + // was dropped), and past the queue it is refused unchecked: either way no work is done on it now. + assert.ok((metrics['relayed-signer-muted'] || 0) + (metrics['cmb-queued'] || 0) + (metrics['cmb-queue-refused'] || 0) >= 380, 'the rest waits or is refused before any work'); assert.ok(logs.length <= 10, `log lines: ${logs.length}`); assert.ok(b._decisionLog.count() - before <= 2, 'decision-log entries bounded'); } finally { await stopAll(b); } @@ -134,7 +136,7 @@ describe('3: relayed forgeries cost bounded work, and nobody is blamed (Finding }); describe('3b: the verification lane bounds work on records naming many signers', () => { - it('400 records naming 400 unknown authors: most are dropped before any schema, hash or signature work', async () => { + it('400 records naming 400 unknown authors: most wait (or are refused) before any schema, hash or signature work', async () => { const b = mk('lane', {}); try { await b.start(); @@ -148,7 +150,10 @@ describe('3b: the verification lane bounds work on records naming many signers', rec.metadata.createdByNodeId = crypto.randomUUID(); deliver(b, sM, { type: 'cmb', cmb: rec }); } - assert.ok((metrics['cmb-over-verify-budget'] || 0) >= 200, `dropped before any work: ${metrics['cmb-over-verify-budget']}`); + // They wait in the session's queue and are checked at the lane's rate (flow control, 0.14.3: they were dropped). + const waiting = (metrics['cmb-queued'] || 0) + (metrics['cmb-queue-refused'] || 0); + assert.ok(waiting >= 200, `waiting or refused before any work: ${waiting}`); + assert.ok((metrics['cmb-author-unresolvable'] || 0) <= 128 + 8, `and only the lane's burst was checked now (${metrics['cmb-author-unresolvable']})`); } finally { await stopAll(b); } }); }); diff --git a/tests/core-secure-review.test.js b/tests/core-secure-review.test.js index 3cc06031..6c354b8c 100644 --- a/tests/core-secure-review.test.js +++ b/tests/core-secure-review.test.js @@ -235,7 +235,7 @@ describe('D. no shared budget before verification; bounds (cs-review-B, cs-revie assert.ok(resMs < 500, `resolved in ${resMs.toFixed(0)} ms`); }); - it('record-flood: one peer\'s distinct records are evaluated at most at the session budget', async () => { + it('record-flood: one peer\'s distinct records are evaluated at most at the session budget; the rest waits', async () => { const N = mk('rf-n', { room: 'g' }); const E = mk('rf-e', { room: 'g' }); try { await N.start(); await E.start(); @@ -245,11 +245,11 @@ describe('D. no shared budget before verification; bounds (cs-review-B, cs-revie const author = { nodeId: E.nodeId, name: E.name, publicKey: E._identity.publicKey, privateKey: E._identity.privateKey }; const s = E._peers.get(N.nodeId).transport; const metrics = []; - N.on('metric', (m) => { if (m.type === 'cmb-over-budget') metrics.push(m); }); + N.on('metric', (m) => { if (m.type === 'cmb-queued') metrics.push(m); }); for (let i = 0; i < 120; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'g', categories: { focus: `distinct record ${i}` } }) }); await until(() => metrics.length + evaluated >= 120, 4000); assert.ok(evaluated <= 32 + 8 * 4, `evaluated ${evaluated}: the burst (32) and 8 a second`); - assert.ok(metrics.length >= 50, 'the rest dropped unevaluated, and counted'); + assert.ok(metrics.length >= 50, 'the rest waits in the session\'s queue (flow control, 0.14.3: it was dropped unevaluated), counted'); } finally { await stopAll(N, E); } }); diff --git a/tests/flow-control-bounds.test.js b/tests/flow-control-bounds.test.js new file mode 100644 index 00000000..f8ef3424 --- /dev/null +++ b/tests/flow-control-bounds.test.js @@ -0,0 +1,719 @@ +'use strict'; + +require('./_isolate-home'); // redirect $HOME before lib/config loads +process.env.SYM_SEMANTIC_ENCODER = process.env.SYM_SEMANTIC_ENCODER || 'off'; // what is measured here is not SVAF + +/** + * Flow control (0.14.3): the receiver's bounds, the two control frames, and what a sender does when + * it is told. See tests/flow-control.test.js for delivery end to end and lib/flow-control.js for the + * design. Every test here fails on 9f6847c (most because what it checks is new: the queue, the + * frames, the held list's new states) and passes now; each guard the design adds is pinned by one. + */ + +const { describe, it } = require('node:test'); +const assert = require('node:assert'); +const fs = require('fs'); +const { SymNode } = require('../lib/node'); +const { NullDiscovery, BonjourDiscovery } = require('../lib/discovery'); +const { nodeDirById } = require('../lib/config'); +const { connectNodes, until, signedRecord } = require('./_core-secure'); + +const uniq = (b) => `${b}-${Date.now()}-${Math.random().toString(36).slice(2, 6)}`; +const sleep = (ms) => new Promise((r) => setTimeout(r, ms)); +const CATS = (focus) => ({ focus, issue: 'flow control', intent: 'deliver', motivation: 'm', commitment: 'c', perspective: 'p', mood: { text: 'calm', valence: 0, arousal: 0 } }); +const big = (n, seed) => { let t = ''; let j = 0; while (t.length < n) t += `queue bound ${seed} line ${j++} `; return t.slice(0, n); }; +function mk(base, extra = {}) { return new SymNode({ name: uniq(base), silent: true, discovery: new NullDiscovery(), room: extra.room || 'flow', ...extra }); } +async function stopAll(...nodes) { + for (const n of nodes) { try { await n.stop(); } catch { /* */ } } + for (const n of nodes) { try { fs.rmSync(nodeDirById(n.nodeId), { recursive: true, force: true }); } catch { /* */ } } +} +function metrics(node) { + const by = {}; + node.on('metric', (m) => { (by[m.type] || (by[m.type] = [])).push(m); }); + by.count = (t) => (by[t] || []).length; + return by; +} +/** A node's identity as the test helpers take it (to sign records in its name). */ +const authorOf = (n) => ({ nodeId: n.nodeId, name: n.name, publicKey: n._identity.publicKey, privateKey: n._identity.privateKey }); +/** Make `node` send as 0.14.2 does: every record written at once, whatever the receiver says. */ +const asLegacySender = (node) => { if (typeof node._flowSession === 'function') node._flowSession = () => false; }; +/** The refusal frames a node receives, as they arrive (frame-handler dispatch). */ +function refusalsAt(node) { + const got = []; + const orig = node._frameHandler._dispatch.bind(node._frameHandler); + node._frameHandler._dispatch = (session, peerId, peerName, msg) => { + if (msg && msg.type === 'cmb-refused') got.push({ at: Date.now(), frame: JSON.parse(JSON.stringify(msg)) }); + return orig(session, peerId, peerName, msg); + }; + return got; +} +const flowOf = (n) => (n.status().flowControl || {}).receiver || {}; +/** Count record frames on a pipe, by direction, with when each went. */ +function pipeTap() { + const frames = []; + return { frames, tap: (f, dir) => { if (f && f.type === 'cmb-encrypted') frames.push({ dir, at: Date.now() }); } }; +} + +describe('flow control, the receiver: past its budget a record waits; past its queue it is refused and its sender told', () => { + it('a flood from a peer that ignores everything: the work stays within the budget, the queue within its bound, every refusal is reported, and the peer is cut', async () => { + const N = mk('fb-n'); const E = mk('fb-e'); + asLegacySender(E); + const nm = metrics(N); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const refused = refusalsAt(E); + // The work: records that passed every check and are evaluated (the host hook fires for each). + const spent = []; + N.on('verified-record', () => spent.push(Date.now())); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + const sent = new Set(); + const wave = (from, n) => { + for (let i = from; i < from + n; i++) { + const cmb = signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `flood ${i}` } }); + sent.add(cmb.metadata.assertionId); + if (!s.send({ type: 'cmb', cmb })) break; + } + }; + const t0 = Date.now(); + wave(0, 1700); + assert.ok(await until(() => refused.length > 0, 5000), 'told'); + assert.strictEqual(flowOf(N).cut, 0, 'refusals before the peer was told never count toward the cut'); + wave(1700, 600); // and it keeps on, told + assert.ok(await until(() => s.closed || nm.count('record-flood-cut') > 0, 15000), 'the peer that kept on past its queue after it was told was cut'); + const elapsed = (Date.now() - t0) / 1000; + const f = flowOf(N); + assert.ok(spent.length <= 32 + 8 * elapsed + 2, `the work stayed within the budget (${spent.length} evaluated in ${elapsed.toFixed(1)} s)`); + assert.ok(f.peakRecords <= 512, `the queue held at most 512 of the session's records (${f.peakRecords})`); + assert.ok(f.refused > 1000, `past it, records were refused (${f.refused})`); + assert.ok(f.notices >= 1 && f.notices <= Math.ceil(elapsed) + 2, `the sender was told, at most once a second (${f.notices} notices in ${elapsed.toFixed(1)} s)`); + assert.ok(f.unlisted > 0, 'refusals past what a notice can carry were counted, not listed'); + assert.ok(refused.length >= 1, 'the refusal reached the sender'); + for (const r of refused) { + assert.ok(r.frame.assertionIds.length >= 1 && r.frame.assertionIds.length <= 256, 'a notice names at most 256 records'); + assert.ok(r.frame.assertionIds.every((id) => sent.has(id)), 'and only records this peer sent'); + assert.ok(Number.isInteger(r.frame.retryAfterMs) && r.frame.retryAfterMs >= 1000 && r.frame.retryAfterMs <= 64000, `with a retry-after within its bounds (${r.frame.retryAfterMs})`); + } + assert.ok(refused[0].frame.retryAfterMs >= 30000, `the retry-after is the time the full queue needs to drain (${refused[0].frame.retryAfterMs} ms for ~512 records at 8/s)`); + assert.ok(N._floodPenalised(E.nodeId), 'and its peer is not admitted again for a while'); + assert.ok(await until(() => flowOf(N).queuedRecords === 0, 3000), `what it had queued is dropped, not evaluated (${flowOf(N).queuedRecords} left)`); + assert.ok(nm.count('cmb-queue-dropped') > 100); + assert.ok(nm.count('cmb-queue-refused') === f.refused && nm.count('cmb-queued') === f.queued, 'every refusal and every queued record is a metric'); + } finally { await stopAll(N, E); } + }); + + it('large records: the queue is bounded by size as well (8 Mi characters a session)', async () => { + const N = mk('fs-n'); const E = mk('fs-e'); + asLegacySender(E); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + for (let i = 0; i < 40; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: big(200000, `f${i}`), issue: big(200000, `i${i}`) } }) }); + assert.ok(await until(() => flowOf(N).refused > 0, 10000), 'past 8 Mi characters, records are refused'); + const f = flowOf(N); + assert.ok(f.peakChars <= 8 * 1024 * 1024, `the queue held at most 8 Mi characters (${f.peakChars})`); + assert.ok(f.peakRecords >= 15, `which is ~20 records of 400 K (${f.peakRecords})`); + } finally { await stopAll(N, E); } + }); + + it('the queue in all is bounded by count: a record past it is refused for whichever session brings it, its sender told when to retry, never cut', async () => { + const N = mk('ft-n'); const E1 = mk('ft-e1'); const E2 = mk('ft-e2'); + asLegacySender(E1); asLegacySender(E2); + const nm = metrics(N); + try { + await N.start(); await E1.start(); await E2.start(); + N._frameHandler._admission.limits.totalRecords = 40; + N._frameHandler._admission.limits.refusalsBeforeCut = 5; + await connectNodes(E1, N); await connectNodes(E2, N); + const told2 = refusalsAt(E2); + for (const [E, tag] of [[E1, 'a'], [E2, 'b']]) { + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + for (let i = 0; i < 100; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `total ${tag} ${i}` } }) }); + // E1's queue holds the queue in all for the rest of the test: its session's lane, spent far ahead. + if (E === E1) { + assert.ok(await until(() => flowOf(N).queuedRecords === 40, 3000)); + N._peers.get(E1.nodeId).transport._recordBucket = { tokens: -1e6, at: Date.now() }; + } + await sleep(200); + } + assert.ok(await until(() => told2.length > 0, 5000), 'the second sender was told'); + // Told, it sends on while the queue in all is still full (others' records): refused, never cut. + const s2 = E2._peers.get(N.nodeId).transport; + for (let i = 100; i < 120; i++) s2.send({ type: 'cmb', cmb: signedRecord(authorOf(E2), { room: 'flow', to: N.nodeId, categories: { focus: `total b ${i}` } }) }); + await sleep(300); + const f = flowOf(N); + assert.ok(f.peakRecords <= 40, `at most the total bound waited (${f.peakRecords})`); + assert.ok(f.refused >= 90, `the rest was refused (${f.refused})`); + assert.ok((nm['cmb-queue-refused'] || []).every((m) => m.reason === 'queue-full'), 'for the queue in all'); + assert.ok(told2[0].frame.retryAfterMs >= 3000, `told to retry once the longest queue has drained (${told2[0].frame.retryAfterMs} ms; ~40 records at 8/s)`); + assert.ok(f.refused >= 108, `E2's records sent after it was told were refused too (${f.refused})`); + assert.strictEqual(f.cut, 0, 'a sender refused for others\' records is never cut'); + assert.ok(!E1._peers.get(N.nodeId).transport.closed && !E2._peers.get(N.nodeId).transport.closed); + } finally { await stopAll(N, E1, E2); } + }); + + it('the queue in all is bounded by size too', async () => { + const N = mk('fc-n'); const E = mk('fc-e'); + asLegacySender(E); + try { + await N.start(); await E.start(); + N._frameHandler._admission.limits.totalChars = 300 * 1024; + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + // 100 records of 60 K: the first ~25 within the 1.5 Mi burst, then the queue, at most 300 K of it. + for (let i = 0; i < 100; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: big(60000, `c${i}`) } }) }); + assert.ok(await until(() => flowOf(N).refused > 0, 10000)); + const f = flowOf(N); + assert.ok(f.peakChars <= 300 * 1024, `the queue in all held at most its size bound (${f.peakChars})`); + assert.ok(f.peakRecords <= 5, `about 5 records of 60 K (${f.peakRecords})`); + } finally { await stopAll(N, E); } + }); + + it('a peer no longer admitted while its records wait: what it queued is dropped, counted, never evaluated', async () => { + const N = mk('fd-n'); const E = mk('fd-e'); + asLegacySender(E); + const nm = metrics(N); + let patched = false; + let after = 0; + // Raised synchronously when a record is admitted, before anything is evaluated. + N.on('verified-record', () => { if (patched) after++; }); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + for (let i = 0; i < 60; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `door ${i}` } }) }); + assert.ok(await until(() => nm.count('cmb-queued') >= 20, 5000), 'records past the budget wait'); + // The door now refuses that peer (evicted from the room, say): what waits for it is not admitted. + const door = N._roomDoor.bind(N); + N._roomDoor = (peerId) => (peerId === E.nodeId ? { pass: false, reason: 'evicted' } : door(peerId)); + patched = true; + assert.ok(await until(() => nm.count('cmb-queue-dropped') > 0 && flowOf(N).queuedRecords === 0, 8000), 'what waited was dropped'); + await sleep(300); + assert.strictEqual(after, 0, 'nothing that waited was admitted once the door refused its peer'); + assert.ok(nm['cmb-queue-dropped'].every((m) => m.reason === 'not-admitted')); + } finally { await stopAll(N, E); } + }); + + it('a peer penalised for a forgery while its records wait: what it queued is dropped', async () => { + const N = mk('fpn-n'); const E = mk('fpn-e'); + asLegacySender(E); + const nm = metrics(N); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + for (let i = 0; i < 60; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `penalty ${i}` } }) }); + assert.ok(await until(() => nm.count('cmb-queued') >= 20, 5000)); + if (!N._forgeryPenalty) N._forgeryPenalty = new Map(); + N._forgeryPenalty.set(E.nodeId, Date.now() + 60_000); + assert.ok(await until(() => flowOf(N).queuedRecords === 0, 3000), 'dropped at once'); + assert.ok(nm.count('cmb-queue-dropped') >= 20); + } finally { await stopAll(N, E); } + }); + + it('a session\'s records are admitted in arrival order: a small one never overtakes a large one waiting for the size budget', async () => { + const N = mk('fo-n'); const E = mk('fo-e'); + asLegacySender(E); + // The order records are ADMITTED in: the hook is raised synchronously at admission, for a record and a + // message alike (a large record's cmb-accepted comes after its evaluation, which is asynchronous). + const seen = []; + N.on('verified-record', (e) => { const f = e.record.categories.focus; const t = (f && f.text) || f; if (/^order /.test(t)) seen.push(/^order big/.test(t) ? t.slice(0, 12) : t); }); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + for (let i = 0; i < 12; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `order big ${String(i).padStart(2, '0')} ${big(200000, `o${i}`)}` } }) }); + await sleep(100); + for (let i = 0; i < 3; i++) E.send(`order small ${i}`, { to: N.nodeId }); + assert.ok(await until(() => seen.length === 15, 30000), `all surfaced (${seen.length})`); + assert.deepStrictEqual(seen.slice(12), ['order small 0', 'order small 1', 'order small 2'], 'the small ones after every large one before them'); + } finally { await stopAll(N, E); } + }); + + it('a notice goes at most once a second, whatever asks for it (a new session of the peer included), and what waits is sent a second later', async () => { + const { RecordAdmission } = require('../lib/flow-control'); + const sent = []; + const session = { nodeId: 'p', confirmed: true, closed: false, trySend: (f) => { sent.push({ f, at: Date.now() }); return { ok: true }; } }; + const adm = new RecordAdmission({ wait: () => 1000, run: () => {}, admitted: () => true, sessionFor: () => session, cut: () => {}, fail: () => {}, metric: () => {}, say: () => {} }); + adm.limits.queueRecords = 0; + const msg = (i) => ({ cmb: { metadata: { assertionId: `asrt-${i.toString(16).padStart(64, '0')}` } } }); + let flushes = 0; + const flush = adm.flush.bind(adm); + adm.flush = (...a) => { flushes++; return flush(...a); }; + adm.offer(session, 'p', 'p', msg(1), 100); + adm.flush('p'); + assert.strictEqual(sent.length, 1, 'the first notice goes at once'); + adm.offer(session, 'p', 'p', msg(2), 100); + adm.flushFor('p'); + adm.flush('p'); + assert.strictEqual(sent.length, 1, 'a second within the second waits'); + flushes = 0; + await until(() => sent.length === 2, 2000); + assert.strictEqual(sent.length, 2, 'and goes a second after the first'); + assert.ok(sent[1].at - sent[0].at >= 990, `${sent[1].at - sent[0].at} ms apart`); + assert.ok(flushes <= 3, `one timer waited the second out, nothing spun (${flushes} flushes)`); + adm.stop(); + }); + + it('only a peer that keeps on past ITS OWN queue in one episode is cut: refusals start over once its queue has drained', async () => { + const N = mk('fe-n'); const E = mk('fe-e'); + asLegacySender(E); + try { + await N.start(); await E.start(); + N._frameHandler._admission.limits.queueRecords = 8; + N._frameHandler._admission.limits.refusalsBeforeCut = 20; + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const author = authorOf(E); + const told = refusalsAt(E); + const send = (tag, from, n) => { for (let i = from; i < from + n; i++) s.send({ type: 'cmb', cmb: signedRecord(author, { room: 'flow', to: N.nodeId, categories: { focus: `episode ${tag} ${i}` } }) }); }; + // An episode: a burst past the queue (32 now, 8 queued, the rest refused before the peer is + // told), then, told, `after` more while its queue is still full. + const episode = async (tag, after) => { + const n = told.length; + send(tag, 0, 60); + assert.ok(await until(() => told.length > n, 5000), `told in episode ${tag}`); + send(tag, 60, after); + await until(() => flowOf(N).queuedRecords === 0, 15000); + await sleep(1100); + }; + await episode('a', 15); + await episode('b', 15); + assert.strictEqual(flowOf(N).cut, 0, 'two episodes under the bound (15 refused after being told, of 20) do not add up to a cut'); + assert.ok(!s.closed); + await episode('c', 40); + assert.ok(await until(() => flowOf(N).cut === 1, 8000), 'one episode past the bound is a cut'); + } finally { await stopAll(N, E); } + }); + + it('copies of a record already delivered spend the pre-verification lane: at most its burst and 32 a second are checked', async () => { + const N = mk('fv-n'); const E = mk('fv-e'); + asLegacySender(E); + const nm = metrics(N); + try { + await N.start(); await E.start(); + await connectNodes(E, N); + const s = E._peers.get(N.nodeId).transport; + const rec = signedRecord(authorOf(E), { room: 'flow', to: N.nodeId, categories: { focus: 'once only' } }); + s.send({ type: 'cmb', cmb: rec }); + assert.ok(await until(() => N._frameHandler._ledger.size > 0, 5000), 'the record surfaced'); + await sleep(4500); // the lanes refill + const t0 = Date.now(); + for (let i = 0; i < 400; i++) s.send({ type: 'cmb', cmb: JSON.parse(JSON.stringify(rec)) }); + await sleep(1000); + const t = (Date.now() - t0) / 1000; + const checked = nm.count('cmb-already-delivered'); + assert.ok(checked >= 100, `the burst was checked (${checked})`); + assert.ok(checked <= 128 + 32 * t + 4, `and no more than the lane holds (${checked} in ${t.toFixed(1)} s)`); + assert.ok(await until(() => nm.count('cmb-already-delivered') === 400, 15000), `every copy was checked in the end, none dropped unchecked (${nm.count('cmb-already-delivered')} of 400)`); + } finally { await stopAll(N, E); } + }); + + it('the node stopping refuses what waits and tells the sender, which offers it again to the next session: every record surfaces once', async () => { + const room = uniq('flow-stop'); + const s = new SymNode({ name: uniq('fz-s'), room, silent: true, discovery: new BonjourDiscovery({ mdns: false, room }) }); + const r = new SymNode({ name: uniq('fz-r'), room, silent: true, discovery: new BonjourDiscovery({ mdns: false, room }) }); + const seen = []; + r.on('cmb-accepted', (e) => { const t = e.cmb.categories.focus.text || e.cmb.categories.focus; if (/^stop /.test(t)) seen.push(t); }); + const sm = metrics(s); + try { + // r advertises far more than it keeps, so s writes the whole burst at once and r queues most of it. + const fb = r._frameHandler.flowBudget.bind(r._frameHandler); + r._frameHandler.flowBudget = () => ({ ...fb(), recordsPerSecond: 1000, recordsBurst: 1000, charsPerSecond: 1e9, charsBurst: 1e9 }); + await s.start(); await r.start(); + assert.ok(await until(() => s._peers.has(r.nodeId) && r._peers.has(s.nodeId), 20000)); + assert.ok(await until(() => s._peers.get(r.nodeId).transport._outFlow && s._peers.get(r.nodeId).transport._outFlow.advertised, 5000)); + for (let i = 0; i < 100; i++) s.remember(CATS(`stop ${i}`), { to: r.nodeId }); + // Every record has reached r (surfaced or waiting): what is still unread in a socket when it closes + // is the residual (lost with the socket, said nowhere), not what this test is about. + assert.ok(await until(() => seen.length + flowOf(r).queuedRecords === 100, 10000), `r holds all 100 (${seen.length} surfaced, ${flowOf(r).queuedRecords} waiting)`); + assert.ok(flowOf(r).queuedRecords > 20, `r has records waiting (${flowOf(r).queuedRecords})`); + await r.stop(); + assert.ok(await until(() => sm.count('cmb-refused-by-peer') > 0, 5000), 'the stopping receiver told the sender what it had not taken'); + assert.ok(s.pendingDeliveries().some((p) => p.state === 'refused'), 'held again, waiting for the retry-after'); + await r.start(); + setTimeout(() => { try { s._discovery._scanLoopback(); r._discovery._scanLoopback(); } catch { /* */ } }, 300); + assert.ok(await until(() => new Set(seen).size === 100 && s.pendingDeliveries().length === 0, 40000), `every record surfaced (${new Set(seen).size} of 100; pending ${s.pendingDeliveries().length})`); + assert.strictEqual(seen.length, 100, 'each once'); + assert.strictEqual(sm.count('cmb-undelivered'), 0); + } finally { await stopAll(s, r); } + }); +}); + +describe('flow control, the advertisement (`cmb-budget`)', () => { + it('once a session is admitted each side advertises its record budget and queue bound, and the other paces to it', async () => { + const a = mk('fa-a'); const b = mk('fa-b'); + const am = metrics(a); + try { + await a.start(); await b.start(); + await connectNodes(a, b); + assert.ok(await until(() => am.count('peer-budget') > 0, 3000), 'a heard b\'s budget'); + const flow = a._peers.get(b.nodeId).transport._outFlow; + assert.ok(flow && flow.advertised); + assert.deepStrictEqual({ ...flow.budget }, { recordsPerSecond: 8, recordsBurst: 32, charsPerSecond: 131072, charsBurst: 1572864, queueRecords: 512, queueChars: 8388608 }); + const back = b._peers.get(a.nodeId).transport._outFlow; + assert.ok(back && back.advertised, 'and b heard a\'s'); + } finally { await stopAll(a, b); } + }); + + it('a malformed advertisement or refusal notice is refused, counted, and changes nothing', async () => { + const a = mk('fm-a'); const b = mk('fm-b'); + try { + await a.start(); await b.start(); + await connectNodes(a, b); + await until(() => a._peers.get(b.nodeId).transport._outFlow && a._peers.get(b.nodeId).transport._outFlow.advertised, 3000); + const s = b._peers.get(a.nodeId).transport; + const good = { type: 'cmb-budget', recordsPerSecond: 8, recordsBurst: 32, charsPerSecond: 131072, charsBurst: 1572864, queueRecords: 512, queueChars: 8388608 }; + const id = `asrt-${'a'.repeat(64)}`; + const bad = [ + { ...good, extra: 1 }, + { ...good, recordsPerSecond: -1 }, + { ...good, recordsBurst: 0 }, + { ...good, charsPerSecond: 'fast' }, + { ...good, charsBurst: Infinity }, + { ...good, queueRecords: -5 }, + (() => { const g = { ...good }; delete g.queueChars; return g; })(), + { type: 'cmb-refused', assertionIds: [id], retryAfterMs: 1000, extra: true }, + { type: 'cmb-refused', assertionIds: [], retryAfterMs: 1000 }, + { type: 'cmb-refused', assertionIds: ['asrt-zz'], retryAfterMs: 1000 }, + { type: 'cmb-refused', assertionIds: Array.from({ length: 257 }, (_, i) => `asrt-${i.toString(16).padStart(64, '0')}`), retryAfterMs: 1000 }, + { type: 'cmb-refused', assertionIds: [id], retryAfterMs: 1.5 }, + { type: 'cmb-refused', assertionIds: [id], retryAfterMs: -1 }, + { type: 'cmb-refused', assertionIds: [id] }, + ]; + const before = a._sessionStats.refusedByReason.malformed || 0; + for (const f of bad) s.send(f); + await until(() => (a._sessionStats.refusedByReason.malformed || 0) - before === bad.length, 3000); + assert.strictEqual((a._sessionStats.refusedByReason.malformed || 0) - before, bad.length, 'each malformed frame was refused and counted'); + const flow = a._peers.get(b.nodeId).transport._outFlow; + assert.strictEqual(flow.budget.recordsPerSecond, 8, 'the budget is unchanged'); + assert.strictEqual(flow.backoffUntil, 0, 'and nothing was backed off'); + } finally { await stopAll(a, b); } + }); + + it('before, or without, an advertisement a peer is paced to 0.14.2\'s budget with a margin: 24 at once, then 6 a second', async () => { + const s = mk('fl-s'); const r = mk('fl-r'); + // r advertises nothing (as 0.14.2). + r._frameHandler.flowBudget = () => ({ type: 'x-not-a-budget' }); + const { frames, tap } = pipeTap(); + try { + await s.start(); await r.start(); + await connectNodes(s, r, { tap }); + await sleep(300); + const t0 = Date.now(); + for (let i = 0; i < 60; i++) s.send(`legacy pace ${i}`, { to: r.nodeId }); + await sleep(1000); + const toR = () => frames.filter((f) => f.dir === 'a→b' && f.at >= t0); + // Within 300 ms of the first: the burst of 24, and at 6 a second at most one or two more. + const first = toR()[0].at; + const inFirst = toR().filter((f) => f.at - first < 300).length; + assert.ok(inFirst <= 26, `at most 24 at once (${inFirst} in the first 300 ms)`); + assert.ok(inFirst >= 20, `and the burst went at once (${inFirst})`); + const inSecond = toR().length; + assert.ok(inSecond <= 24 + 7, `then about 6 a second (${inSecond} in the first second)`); + } finally { await stopAll(s, r); } + }); + + it('anchors spend the session\'s budget: the burst after them is what the receiver still holds', async () => { + const s = mk('fan-s'); const r = mk('fan-r'); + try { + await s.start(); await r.start(); + for (let i = 0; i < 5; i++) s.remember(CATS(`anchor ${i}`)); + await connectNodes(s, r); + assert.ok(await until(() => s._peers.get(r.nodeId).transport._outFlow && s._peers.get(r.nodeId).transport._outFlow.advertised, 3000)); + await sleep(50); + for (let i = 0; i < 40; i++) s.send(`after anchors ${i}`, { to: r.nodeId }); + await sleep(1500); + const f = flowOf(r); + assert.ok(f.peakRecords <= 3, `the receiver never had more than jitter waiting (${f.peakRecords})`); + } finally { await stopAll(s, r); } + }); + + it('an advertisement that arrives after records were sent starts from what the receiver can still hold (its burst less what was sent)', async () => { + const s = mk('fla-s'); const r = mk('fla-r'); + const fb = r._frameHandler.flowBudget.bind(r._frameHandler); + // r advertises nothing at first, then (400 ms later) its real budget. + r._frameHandler.flowBudget = () => ({ type: 'x-not-yet' }); + const greet = r._greetSession.bind(r); + r._greetSession = (peer, session, isNew) => { greet(peer, session, isNew); setTimeout(() => { if (!session.closed) session.send(fb()); }, 400); }; + try { + await s.start(); await r.start(); + await connectNodes(s, r); + const t0 = Date.now(); + for (let i = 0; i < 60; i++) s.send(`late budget ${i}`, { to: r.nodeId }); + assert.ok(await until(() => s._peers.get(r.nodeId).transport._outFlow.advertised, 3000)); + await until(() => Date.now() - t0 > 2500, 3000); + const f = flowOf(r); + assert.ok(f.peakRecords <= 4, `the receiver never had more than jitter waiting (${f.peakRecords})`); + assert.strictEqual(f.refused, 0); + } finally { await stopAll(s, r); } + }); +}); + +describe('flow control, the sender told a record was refused (`cmb-refused`)', () => { + it('refused records are held again in their place and offered first after the retry-after, nothing goes to that session meanwhile, and every record surfaces once', async () => { + const s = mk('fr-s'); const r = mk('fr-r'); + const fb = r._frameHandler.flowBudget.bind(r._frameHandler); + // r advertises more than it keeps: 60 at once and 20 a second (it keeps 32 and 8, and queues 16). + r._frameHandler.flowBudget = () => ({ ...fb(), recordsPerSecond: 20, recordsBurst: 60, charsPerSecond: 1e9, charsBurst: 1e9 }); + const seen = []; + r.on('message', (_f, t) => seen.push(t)); + const sm = metrics(s); + const { frames, tap } = pipeTap(); + try { + await s.start(); await r.start(); + r._frameHandler._admission.limits.queueRecords = 16; + await connectNodes(s, r, { tap }); + const told = refusalsAt(s); + assert.ok(await until(() => s._peers.get(r.nodeId).transport._outFlow.advertised, 3000)); + // 60 written at once, 40 held for the (advertised) budget; past r's queue some of the 60 are refused. + for (let i = 0; i < 100; i++) s.send(`refused ${i}`, { to: r.nodeId }); + assert.ok(await until(() => told.length > 0, 5000), 'the sender was told'); + const first = told[0]; + // Sent while the session is backed off: they wait for the retry-after too. + for (let i = 100; i < 105; i++) s.send(`refused ${i}`, { to: r.nodeId }); + assert.ok(await until(() => new Set(seen).size === 105 && s.pendingDeliveries().length === 0, 40000), `every record surfaced (${new Set(seen).size} of 105)`); + assert.strictEqual(seen.length, 105, 'each once'); + // 32 now and 16 queued, in order; after the retry-after the first refused record goes first, + // ahead of the 40 held behind it. (Later, a record written before the next notice reaches the + // sender can be taken ahead of one refused: order across a refusal is not kept, see CHANGELOG.) + assert.deepStrictEqual(seen.slice(0, 49), Array.from({ length: 49 }, (_, i) => `refused ${i}`), 'a refused record went back in its place, ahead of those held behind it'); + const quiet = frames.filter((f) => f.dir === 'a→b' && f.at > first.at + 50 && f.at < first.at + first.frame.retryAfterMs - 50); + assert.deepStrictEqual(quiet, [], `nothing was written to that session during the ${first.frame.retryAfterMs} ms retry-after`); + assert.ok((sm['cmb-requeued'] || []).some((m) => m.reason === 'refused'), 'refused records were requeued'); + assert.ok(sm.count('cmb-refused-by-peer') >= 1); + assert.strictEqual(sm.count('cmb-undelivered'), 0); + assert.strictEqual(flowOf(r).cut, 0, 'an honest sender is never cut'); + assert.ok(s.status().flowControl.sender.refusedByPeers > 0, 'counted in status'); + } finally { await stopAll(s, r); } + }); + + it('a refused record waits for its retry-after on any session, a new one included', async () => { + const s = mk('fn-s'); const r = mk('fn-r'); + const got = []; + r.on('message', (_f, t) => got.push({ t, at: Date.now() })); + try { + await s.start(); await r.start(); + // r refuses the first record it is brought (its queue in all full of others'), then takes them. + const adm = r._frameHandler._admission; + const offer = adm.offer.bind(adm); + let once = false; + adm.offer = (session, peerId, peerName, msg, chars) => { + if (!once) { once = true; return adm._refuse({ session, peerId, peerName, msg, chars }, 'queue-full', Date.now()); } + return offer(session, peerId, peerName, msg, chars); + }; + await connectNodes(s, r); + const told = refusalsAt(s); + await sleep(200); + s.send('wait for it', { to: r.nodeId }); + assert.ok(await until(() => told.length > 0, 3000), 'refused, and told'); + const retryAt = told[0].at + told[0].frame.retryAfterMs; + // A new session supersedes the old one at once: it has no back-off of its own. + await connectNodes(s, r); + assert.ok(await until(() => got.length === 1, 5000), 'delivered on the new session'); + assert.ok(got[0].at >= retryAt - 50, `not before the retry-after (${got[0].at - retryAt} ms after it)`); + } finally { await stopAll(s, r); } + }); + + it('a record refused more than 8 times is given up: said undelivered, listed, raised as an event, and no longer pending', async () => { + const s = mk('fg-s'); const r = mk('fg-r'); + const events = []; + s.on('undelivered', (u) => events.push(u)); + try { + await s.start(); await r.start(); + // r refuses every record (its queue in all is full of others'). + const adm = r._frameHandler._admission; + adm.offer = (session, peerId, peerName, msg, chars) => adm._refuse({ session, peerId, peerName, msg, chars }, 'queue-full', Date.now()); + await connectNodes(s, r); + const told = refusalsAt(s); + await sleep(200); + const e = s.remember(CATS('never taken'), { to: r.nodeId }); + assert.ok(e.delivery.dispatched === 1, 'written within the budget'); + assert.ok(await until(() => events.length > 0, 30000), 'given up'); + assert.strictEqual(events[0].reason, 'refused'); + assert.strictEqual(events[0].refusals, 9, 'after the 8th retry was refused'); + assert.strictEqual(events[0].key, e.key); + assert.deepStrictEqual(s.undelivered().map((u) => [u.key, u.reason]), [[e.key, 'refused']]); + assert.strictEqual(s.pendingDeliveries().length, 0); + assert.strictEqual(s.status().flowControl.sender.undelivered, 1); + assert.strictEqual(flowOf(r).cut, 0); + assert.ok(told.length >= 9 && told.every((t) => t.frame.retryAfterMs >= 1000), 'every notice carried at least the one-second retry-after, even with nothing queued'); + } finally { await stopAll(s, r); } + }); + + it('a room record refused by one peer is retried to that peer only', async () => { + const a = mk('fp-a'); const b = mk('fp-b'); const c = mk('fp-c'); const d = mk('fp-d'); + const at = { b: [], c: [], d: [] }; + b.on('verified-record', (e) => at.b.push(e.record.metadata.key)); + c.on('verified-record', (e) => at.c.push(e.record.metadata.key)); + d.on('verified-record', (e) => at.d.push(e.record.metadata.key)); + const taps = { b: pipeTap(), c: pipeTap(), d: pipeTap() }; + try { + await a.start(); await b.start(); await c.start(); await d.start(); + // c, the second of three peers a broadcasts to, refuses the first record it is brought. + const adm = c._frameHandler._admission; + const offer = adm.offer.bind(adm); + let once = false; + adm.offer = (session, peerId, peerName, msg, chars) => { + if (!once && msg && msg.cmb && msg.cmb.metadata && msg.cmb.metadata.assertionId) { once = true; return adm._refuse({ session, peerId, peerName, msg, chars }, 'queue-full', Date.now()); } + return offer(session, peerId, peerName, msg, chars); + }; + await connectNodes(a, b, { tap: taps.b.tap }); + await connectNodes(a, c, { tap: taps.c.tap }); + await connectNodes(a, d, { tap: taps.d.tap }); + await sleep(300); + const t0 = Date.now(); + const e = a.remember(CATS('to the room')); + assert.ok(await until(() => at.c.includes(e.key), 10000), 'c took it on the retry'); + await sleep(300); + for (const p of ['b', 'c', 'd']) assert.strictEqual(at[p].filter((k) => k === e.key).length, 1, `${p} took it once`); + const frames = (p) => taps[p].frames.filter((f) => f.dir === 'a→b' && f.at >= t0).length; + assert.deepStrictEqual({ b: frames('b'), c: frames('c'), d: frames('d') }, { b: 1, c: 2, d: 1 }, 'only c was sent it again'); + } finally { await stopAll(a, b, c, d); } + }); + + it('a refusal naming a record written over a minute ago (or never) changes nothing, and is counted', async () => { + const s = mk('fw-s'); const r = mk('fw-r'); + const sm = metrics(s); + try { + await s.start(); await r.start(); + await connectNodes(s, r); + await sleep(200); + const e = s.remember(CATS('long gone'), { to: r.nodeId }); + const k = `${r.nodeId}|${e.cmb.metadata.assertionId}`; + assert.ok(s._sentWindow && s._sentWindow.has(k), 'remembered while it may still be refused'); + s._sentWindow.get(k).sentAt -= 61_000; + s._pruneSentWindow(); + r._peers.get(s.nodeId).transport.send({ type: 'cmb-refused', assertionIds: [e.cmb.metadata.assertionId], retryAfterMs: 1000 }); + assert.ok(await until(() => sm.count('cmb-refused-unmatched') > 0, 3000), 'counted as a refusal of nothing held'); + assert.strictEqual(s.pendingDeliveries().length, 0, 'nothing was held again'); + // The peer's queue is full all the same: nothing more goes to it until the retry-after. + const t0 = Date.now(); + const got = []; + r.on('message', (_f, t) => got.push(Date.now())); + assert.ok(s.send('after the refusal', { to: r.nodeId }) === 1, 'taken'); + assert.strictEqual(s.pendingDeliveries().length, 1, 'held for the retry-after'); + assert.ok(await until(() => got.length === 1, 4000)); + assert.ok(got[0] - t0 >= 800, `written once the retry-after had passed (${got[0] - t0} ms)`); + } finally { await stopAll(s, r); } + }); + + it('a record refused while it still waits in the relay pacer (its write not yet seen) is held again when the write is seen, not counted delivered', async () => { + const n = mk('fq-n'); + const to = '01900000-0000-7000-8000-0000000000bb'; + try { + await n.start(); + const metas = []; + const fake = { closed: false, confirmed: true, kind: 'relay', identityKey: 'k', sessionId: 's1', nodeId: to, name: 'fake', pendingBytes: () => 0, + transport: { hasRoom: () => true }, trySend: (frame, meta) => { metas.push(meta); return { ok: true }; }, send: () => true }; + n._peers.set(to, { peerId: to, name: 'fake', transport: fake, transports: new Map([['relay', fake]]) }); + const rec = signedRecord(authorOf(n), { room: 'flow', to, categories: { focus: 'in the pacer' } }); + assert.strictEqual(n._dispatchCmb(rec, Date.now(), to).dispatched, 1, 'written to the session (into the pacer)'); + n._onPeerRefused(fake, { type: 'cmb-refused', assertionIds: [rec.metadata.assertionId], retryAfterMs: 1000 }); + n._redeliveryFlushed(metas[0]); + const p = n.pendingDeliveries(); + assert.strictEqual(p.length, 1, 'still pending'); + assert.strictEqual(p[0].state, 'refused', 'waiting for its retry-after'); + assert.strictEqual(p[0].refusals, 1); + } finally { n._peers.clear(); await stopAll(n); } + }); + + it('a held record older than 23 h by its signed timestamp is given up (a receiver would refuse it as a replay)', async () => { + const s = mk('fx-s'); + const events = []; + s.on('undelivered', (u) => events.push(u)); + try { + await s.start(); + const to = '01900000-0000-7000-8000-0000000000aa'; + const old = signedRecord(authorOf(s), { room: 'flow', to, categories: { focus: 'old' } }); + old.metadata.createdTimestamp = Date.now() - 24 * 3600 * 1000; + s._holdUnflushed([{ to, bytes: 100, meta: { redeliver: true, to, key: 'k', frame: { type: 'cmb', cmb: old }, recordKey: 'cmb-old', since: Date.now(), attempts: 1, held: false, offered: false, bytes: 0 } }]); + assert.strictEqual(s.pendingDeliveries().length, 1, 'held'); + s._sweepHeld(); + assert.strictEqual(s.pendingDeliveries().length, 0, 'and given up'); + assert.deepStrictEqual(events.map((u) => [u.key, u.reason]), [['cmb-old', 'expired']]); + // And a pass that would write one gives it up instead. + const to2 = '01900000-0000-7000-8000-0000000000ab'; + const written = []; + const fake = { closed: false, confirmed: true, kind: 'bonjour', identityKey: 'k2', sessionId: 's9', nodeId: to2, name: 'fake', pendingBytes: () => 0, trySend: (f) => { written.push(f); return { ok: true }; } }; + const old2 = signedRecord(authorOf(s), { room: 'flow', to: to2, categories: { focus: 'old too' } }); + old2.metadata.createdTimestamp = Date.now() - 24 * 3600 * 1000; + s._holdUnflushed([{ to: to2, bytes: 100, meta: { redeliver: true, to: to2, key: 'k2', frame: { type: 'cmb', cmb: old2 }, recordKey: 'cmb-old2', since: Date.now(), attempts: 1, held: false, offered: false, bytes: 0 } }]); + s._reofferHeld(to2, fake); + assert.deepStrictEqual(written, [], 'not written'); + assert.deepStrictEqual(events.map((u) => u.key), ['cmb-old', 'cmb-old2']); + } finally { await stopAll(s); } + }); + + it('a record the session refuses outright on its first write is not held: the send says why, as before', async () => { + const s = mk('fy-s'); + try { + await s.start(); + const { admitAs, identity } = require('./_core-secure'); + const peer = identity('fy-peer'); + const sess = admitAs(s, peer); + sess.trySend = () => ({ ok: false, reason: 'write-failed' }); + const e = s.remember(CATS('the socket failed'), { to: peer.nodeId }); + assert.strictEqual(e.delivery.undelivered, true); + assert.strictEqual(e.delivery.reason, 'write-failed'); + assert.strictEqual(s.pendingDeliveries().length, 0, 'not held'); + } finally { s._peers.clear(); await stopAll(s); } + }); + + it('the held list is bounded by size too: past 8 Mi characters for a peer a new record is not held', async () => { + const s = mk('fk-s'); const r = mk('fk-r'); + try { + await s.start(); await r.start(); + await connectNodes(s, r); + await until(() => s._peers.get(r.nodeId).transport._outFlow && s._peers.get(r.nodeId).transport._outFlow.advertised, 3000); + const body = big(200 * 1024, 'held'); + let taken = 0; + for (let i = 0; i < 60; i++) taken += s.send(`${i} ${body}`, { to: r.nodeId }); + assert.ok(taken >= 25 && taken <= 50, `the held list took what 8 Mi characters hold, past the 1.5 Mi written at once (${taken} of 60)`); + } finally { await stopAll(s, r); } + }); + + it('past the held list\'s bound a new record is not held: a directed send says so (held-full)', async () => { + const s = mk('fh-s'); const r = mk('fh-r'); + try { + await s.start(); await r.start(); + await connectNodes(s, r); + await until(() => s._peers.get(r.nodeId).transport._outFlow && s._peers.get(r.nodeId).transport._outFlow.advertised, 3000); + let taken = 0; + for (let i = 0; i < 2100; i++) taken += s.send(`bound ${i}`, { to: r.nodeId }); + assert.ok(taken < 2100 && taken >= 2048, `the held list took up to its bound (${taken})`); + const e = s.remember(CATS('one too many'), { to: r.nodeId }); + assert.strictEqual(e.delivery.undelivered, true); + assert.strictEqual(e.delivery.reason, 'held-full'); + assert.ok(s.pendingDeliveries().length <= 2048); + } finally { await stopAll(s, r); } + }); +}); + +describe('flow control, the buckets', () => { + it('a clock stepped back refills nothing and takes nothing; a back-off holds a session\'s records until it ends', () => { + const { refillBucket, bucketWait, OutboundBudget } = require('../lib/flow-control'); + const b = { tokens: 5, at: 10_000 }; + refillBucket(b, 8, 32, 9_000); + assert.strictEqual(b.tokens, 5, 'nothing taken by a clock stepped back'); + assert.strictEqual(b.at, 10_000, 'and the bucket keeps its time'); + refillBucket(b, 8, 32, 10_500); + assert.strictEqual(b.tokens, 9); + assert.strictEqual(bucketWait({ tokens: 0, at: 0 }, 8, 32, 1, 0), 125, 'one record at 8 a second waits 125 ms'); + assert.strictEqual(bucketWait({ tokens: 0, at: 0 }, 10, 100, 1000, 0), 10_000, 'a need past the burst waits for the burst'); + const o = new OutboundBudget(0); + assert.strictEqual(o.budget.recordsBurst, 24); + assert.strictEqual(o.wait(100, 0), 0); + o.backOff(2000, 0); + assert.strictEqual(o.wait(100, 1000), 1000, 'a back-off holds what the buckets would allow'); + assert.strictEqual(o.wait(100, 2000), 0); + }); +}); diff --git a/tests/flow-control.test.js b/tests/flow-control.test.js new file mode 100644 index 00000000..49498439 --- /dev/null +++ b/tests/flow-control.test.js @@ -0,0 +1,304 @@ +'use strict'; + +require('./_isolate-home'); // redirect $HOME before lib/config loads +process.env.SYM_SEMANTIC_ENCODER = process.env.SYM_SEMANTIC_ENCODER || 'off'; // what is measured here is not SVAF + +/** + * Flow control for directed and room records (0.14.3): delivery end to end, with real nodes. + * + * A receiver applies a record budget per session (8 a second after a burst of 32; 128 KiB of record + * text a second after 1.5 MiB). Until 0.14.3 a record past it was DROPPED unevaluated while its + * sender reported it dispatched, and nothing offered it again. Measured on 9f6847c (and 0.14.2): + * 49 directed messages in a burst arrived as 38 over a relay (32 over the LAN); 12 records of + * 200 KB as 7; 40 of 50 KB as 30; 120 records held across a relay drop and re-offered as 37, the + * sender saying 115 redelivered. Now the receiver queues what is past its budget (delay, never a + * silent drop), advertises its budget, and the sender paces every record to it. + * + * Every test here fails on 9f6847c (a `git archive` of it) and passes now. The mixed-version tests + * stand a 0.14.3 node in for 0.14.2 the way 0.14.2 behaves (it drops past a count-only budget and + * knows no flow-control frame; it writes everything at once): on 9f6847c the stock node already + * behaves so. The same runs against a real 0.14.2 tree are in the CHANGELOG. + */ + +const { describe, it } = require('node:test'); +const assert = require('node:assert'); +const fs = require('fs'); +const { SymNode } = require('../lib/node'); +const { NullDiscovery, BonjourDiscovery } = require('../lib/discovery'); +const { nodeDirById } = require('../lib/config'); +const { fakeRelay } = require('./_fake-relay'); +const { until } = require('./_core-secure'); + +const TOKEN = 'f'.repeat(40); +const uniq = (b) => `${b}-${Date.now()}-${Math.random().toString(36).slice(2, 6)}`; +const sleep = (ms) => new Promise((r) => setTimeout(r, ms)); +const CATS = (focus, issue = 'flow control') => ({ focus, issue, intent: 'deliver', motivation: 'm', commitment: 'c', perspective: 'p', mood: { text: 'calm', valence: 0, arousal: 0 } }); +const text = (kb, seed) => { let t = ''; let j = 0; while (t.length < kb * 1024) t += `report ${seed} line ${j++} lorem ipsum dolor sit amet `; return t.slice(0, kb * 1024); }; + +/** Two nodes in one room over the LAN (TCP on the loopback, found through the loopback registry). */ +function lanPair(extraR = {}) { + const room = uniq('flow-lan'); + const mk = (n, extra = {}) => new SymNode({ name: uniq(n), room, silent: true, discovery: new BonjourDiscovery({ mdns: false, room }), ...extra }); + return { s: mk('fl-s'), r: mk('fl-r', extraR) }; +} +/** Two nodes in one room over a relay. */ +function relayPair(relay, { sRate } = {}) { + const room = uniq('flow-relay'); + const mk = (n, extra = {}) => new SymNode({ name: uniq(n), room, silent: true, relayOnly: true, relay: relay.url, relayToken: TOKEN, discovery: new NullDiscovery(), ...extra }); + return { s: mk('fr-s', sRate ? { relayRate: sRate } : {}), r: mk('fr-r') }; +} +const paired = (s, r) => () => s._peers.has(r.nodeId) && r._peers.has(s.nodeId); +async function stopAll(...nodes) { + for (const n of nodes) { try { await n.stop(); } catch { /* */ } } + for (const n of nodes) { try { fs.rmSync(nodeDirById(n.nodeId), { recursive: true, force: true }); } catch { /* */ } } +} + +/** What a node surfaced, in order: the focus of each record ('cmb-accepted'), or a message's text. */ +function surfaced(node) { + const seen = []; + node.on('cmb-accepted', (e) => { const f = e && e.cmb && e.cmb.categories && e.cmb.categories.focus; const t = f && (f.text || f); if (typeof t === 'string') seen.push(t); }); + node.on('message', (_from, t) => seen.push(t)); + return seen; +} +/** Every metric a node emits, by type. */ +function metrics(node) { + const by = {}; + node.on('metric', (m) => { (by[m.type] || (by[m.type] = [])).push(m); }); + by.count = (t) => (by[t] || []).length; + return by; +} +const distinct = (seen, re) => new Set(seen.filter((t) => re.test(t))); +const dups = (seen) => seen.length - new Set(seen).size; +const pending = (n) => (typeof n.pendingDeliveries === 'function' ? n.pendingDeliveries().length : 0); + +/** + * The sender's counts are true: everything it took is accounted for — written at once, or held and + * written later — nothing left pending, nothing given up, and every record it held it later wrote. + */ +function assertSenderTrue(s, m, total, { dispatched, queued }) { + assert.strictEqual(dispatched + queued, total, `the sender took every record (${dispatched} written at once, ${queued} held for the budget)`); + assert.strictEqual(pending(s), 0, 'nothing is left pending'); + assert.strictEqual(m.count('cmb-undelivered'), 0, 'nothing was given up'); + const held = new Set((m['cmb-requeued'] || []).map((x) => x.key)); + const written = new Set((m['cmb-redelivered'] || []).map((x) => x.key)); + assert.deepStrictEqual([...written].sort(), [...held].sort(), 'every record it held, it then wrote'); + assert.strictEqual(typeof s.undelivered, 'function', 'the sender lists what it gives up (undelivered())'); + assert.deepStrictEqual(s.undelivered(), []); +} + +/** Send `n` directed records (remember) of `kb` KiB each; count what the sender said of each. */ +function burst(s, to, n, kb, label = 'rec') { + let dispatched = 0; + let queued = 0; + for (let i = 0; i < n; i++) { + const e = s.remember(CATS(`${label} ${i}`, kb ? text(kb, `${label}${i}`) : 'flow control'), { to }); + if (e.delivery.dispatched) dispatched++; + else if (e.delivery.queued) queued++; + } + return { dispatched, queued }; +} + +// ── 0.14.2 as the other end ─────────────────────────────────────────────────────────────────── +/** + * Make `node` receive as 0.14.2 does: a record past its count budget (8 a second, burst 32; 0.14.2 + * had no size budget) is dropped unevaluated, and no flow-control frame is sent or understood. On + * 9f6847c the stock node drops past its budget already (with the size budget too), so nothing is done. + */ +function asLegacyReceiver(node) { + const fh = node._frameHandler; + if (!fh._admission) return; + fh.flowBudget = () => ({ type: 'x-not-a-budget' }); // advertises nothing (a frame a receiver ignores, §7.3) + // 0.14.2's lanes by count only: 32 a second (burst 128) before verification, 8 (burst 32) before SVAF. + const holds = (session, slot, rate, burst) => { + const b = session[slot]; + return !b || Math.min(burst, b.tokens + ((Date.now() - b.at) * rate) / 1000) >= 1; + }; + fh._admission.offer = (session, peerId, peerName, msg, chars) => { + if (!holds(session, '_verifyBucket', 32, 128) || !holds(session, '_recordBucket', 8, 32)) { node.emit('metric', { type: 'cmb-over-budget', from: peerName }); return undefined; } + return fh._admission._o.run({ session, peerId, peerName, msg, chars }); + }; +} +/** Make `node` send as 0.14.2 does: every record written at once, whatever the receiver says. */ +function asLegacySender(node) { + if (typeof node._flowSession === 'function') node._flowSession = () => false; +} + +describe('flow control: honest bursts are delivered, not dropped', () => { + it('49 directed messages sent in one burst over the LAN: all 49 surface, once each and in order, and the sender\'s counts are true', async () => { + const { s, r } = lanPair(); + const seen = surfaced(r); + const m = metrics(s); + const rm = metrics(r); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000), 'paired over the LAN'); + await sleep(300); + let taken = 0; + for (let i = 0; i < 49; i++) taken += s.send(`message number ${i}`, { to: r.nodeId }); + assert.strictEqual(taken, 49, 'the sender took all 49'); + assert.ok(await until(() => distinct(seen, /^message number/).size === 49 && pending(s) === 0, 20000), `all 49 surfaced (${distinct(seen, /^message number/).size})`); + await sleep(300); + assert.strictEqual(dups(seen), 0, 'each once'); + assert.deepStrictEqual(seen.filter((t) => /^message number/.test(t)), Array.from({ length: 49 }, (_, i) => `message number ${i}`), 'in the order sent'); + assert.strictEqual(rm.count('cmb-over-budget') + rm.count('cmb-queue-refused'), 0, 'the receiver dropped and refused nothing'); + assert.strictEqual(pending(s), 0); + assert.strictEqual(m.count('cmb-undelivered'), 0); + } finally { await stopAll(s, r); } + }); + + it('12 directed records of 200 KB over the LAN: all 12 surface once, and the sender says how many it held for the size budget', async () => { + const { s, r } = lanPair(); + const seen = surfaced(r); + const m = metrics(s); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(300); + const counts = burst(s, r.nodeId, 12, 200, 'big'); + assert.ok(counts.queued > 0, `past the 1.5 MiB burst the sender held records for the budget (${counts.queued})`); + assert.ok(await until(() => distinct(seen, /^big /).size === 12 && pending(s) === 0, 40000), `all 12 surfaced (${distinct(seen, /^big /).size})`); + await sleep(300); + assert.strictEqual(dups(seen), 0); + assertSenderTrue(s, m, 12, counts); + } finally { await stopAll(s, r); } + }); + + it('40 directed records of 50 KB over the LAN: all 40 surface once', async () => { + const { s, r } = lanPair(); + const seen = surfaced(r); + const m = metrics(s); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(300); + const counts = burst(s, r.nodeId, 40, 50, 'mid'); + assert.ok(await until(() => distinct(seen, /^mid /).size === 40 && pending(s) === 0, 40000), `all 40 surfaced (${distinct(seen, /^mid /).size})`); + await sleep(300); + assert.strictEqual(dups(seen), 0); + assertSenderTrue(s, m, 40, counts); + } finally { await stopAll(s, r); } + }); + + it('49 directed messages 15 ms apart over a relay (the review\'s r-msgloss): all 49 surface once, in order', async () => { + const relay = fakeRelay(); + const { s, r } = relayPair(relay); + const seen = surfaced(r); + const m = metrics(s); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000), 'paired over the relay'); + await sleep(400); + for (let i = 0; i < 49; i++) { s.send(`message number ${i}`, { to: r.nodeId }); await sleep(15); } + assert.ok(await until(() => distinct(seen, /^message number/).size === 49 && pending(s) === 0, 20000), `all 49 surfaced (${distinct(seen, /^message number/).size})`); + await sleep(300); + assert.strictEqual(dups(seen), 0); + assert.deepStrictEqual(seen.filter((t) => /^message number/.test(t)), Array.from({ length: 49 }, (_, i) => `message number ${i}`), 'in the order sent'); + assert.strictEqual(m.count('cmb-undelivered'), 0); + } finally { await stopAll(s, r); await relay.close(); } + }); +}); + +describe('flow control: records held across a drop are re-offered within the receiver\'s budget', () => { + it('120 directed records across a relay drop (both links cut, the pacer back to 20/s burst 200): all 120 surface once; the sender\'s counts are true', async () => { + let relay = null; + let cut = false; + let rRef = null; + // Both links are cut from inside the receiver's own delivery of the 5th record: nothing of the + // sender's is then in flight in the relay (its pacer writes one frame every 250 ms), so what this + // test measures is the held list and the budget, not the residual. + relay = fakeRelay(); + const { s, r } = relayPair(relay, { sRate: { perSecond: 4, burst: 1 } }); + rRef = r; + const seen = surfaced(r); + r.on('cmb-accepted', () => { + if (!cut && distinct(seen, /^held /).size >= 5) { cut = true; relay.kick(s.nodeId); relay.kick(rRef.nodeId); } + }); + const m = metrics(s); + const rm = metrics(r); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(400); + const counts = burst(s, r.nodeId, 120, 0, 'held'); + assert.ok(await until(() => cut, 15000), 'the links were cut mid-stream'); + // The review's FASTPACER: the re-offer goes out of a pacer that would write 200 frames at once. + s._relay._rate = 20; s._relay._burst = 200; s._relay._bucket = { tokens: 200, at: Date.now() }; + assert.ok(await until(() => distinct(seen, /^held /).size === 120 && pending(s) === 0, 60000), `all 120 surfaced (${distinct(seen, /^held /).size}; pending ${pending(s)})`); + await sleep(500); + assert.strictEqual(dups(seen), 0, 'each once'); + assert.strictEqual(rm.count('cmb-over-budget') + rm.count('cmb-queue-refused'), 0, 'the receiver dropped and refused nothing'); + assertSenderTrue(s, m, 120, counts); + } finally { await stopAll(s, r); await relay.close(); } + }); + + it('120 directed records across a LAN drop: the records not yet written wait, and all 120 surface once on the next session', async () => { + const { s, r } = lanPair(); + const seen = surfaced(r); + let cut = false; + r.on('cmb-accepted', () => { + if (cut || distinct(seen, /^lan /).size < 60) return; + cut = true; + // The receiver's socket closes under the sender, between two of its paced writes. + const sess = r._peers.get(s.nodeId) && r._peers.get(s.nodeId).transports.get('bonjour'); + if (sess && sess.transport) sess.transport.close(); + setTimeout(() => { try { s._discovery._scanLoopback(); r._discovery._scanLoopback(); } catch { /* */ } }, 300); + }); + const m = metrics(s); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(300); + const counts = burst(s, r.nodeId, 120, 0, 'lan'); + assert.ok(await until(() => cut, 20000), 'the LAN connection was cut mid-stream'); + assert.ok(await until(() => distinct(seen, /^lan /).size === 120 && pending(s) === 0, 60000), `all 120 surfaced (${distinct(seen, /^lan /).size}; pending ${pending(s)})`); + await sleep(300); + assert.strictEqual(dups(seen), 0, 'each once'); + assertSenderTrue(s, m, 120, counts); + } finally { await stopAll(s, r); } + }); +}); + +describe('flow control with a 0.14.2 node at the other end', () => { + it('new sender → 0.14.2 receiver (drops past 8/s burst 32, advertises nothing): 49 messages and 12 × 200 KB all surface, none dropped', async () => { + const { s, r } = lanPair(); + asLegacyReceiver(r); + const seen = surfaced(r); + const rm = metrics(r); + const m = metrics(s); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(300); + for (let i = 0; i < 49; i++) s.send(`message number ${i}`, { to: r.nodeId }); + const counts = burst(s, r.nodeId, 12, 200, 'old-big'); + assert.ok(await until(() => distinct(seen, /^message number/).size === 49 && distinct(seen, /^old-big /).size === 12 && pending(s) === 0, 40000), + `all delivered (${distinct(seen, /^message number/).size} of 49 messages, ${distinct(seen, /^old-big /).size} of 12 records)`); + await sleep(300); + assert.strictEqual(rm.count('cmb-over-budget'), 0, 'the old receiver dropped nothing: the sender kept to its budget, with a margin'); + assert.strictEqual(dups(seen), 0); + assert.strictEqual(m.count('cmb-undelivered'), 0); + assert.strictEqual(counts.dispatched + counts.queued, 12); + } finally { await stopAll(s, r); } + }); + + it('0.14.2 sender (writes everything at once, hears nothing) → new receiver: 49 messages and 12 × 200 KB all surface, queued and not dropped', async () => { + const { s, r } = lanPair(); + asLegacySender(s); + const seen = surfaced(r); + const rm = metrics(r); + try { + await s.start(); await r.start(); + assert.ok(await until(paired(s, r), 20000)); + await sleep(300); + for (let i = 0; i < 49; i++) s.send(`message number ${i}`, { to: r.nodeId }); + burst(s, r.nodeId, 12, 200, 'from-old'); + assert.ok(await until(() => distinct(seen, /^message number/).size === 49 && distinct(seen, /^from-old /).size === 12, 40000), + `all delivered (${distinct(seen, /^message number/).size} of 49 messages, ${distinct(seen, /^from-old /).size} of 12 records)`); + await sleep(300); + assert.strictEqual(dups(seen), 0); + assert.ok(rm.count('cmb-queued') > 0, 'what was past the budget waited in the queue'); + assert.strictEqual(rm.count('cmb-queue-refused'), 0, 'and nothing was refused'); + assert.deepStrictEqual(seen.filter((t) => /^message number/.test(t)), Array.from({ length: 49 }, (_, i) => `message number ${i}`), 'in the order sent'); + } finally { await stopAll(s, r); } + }); +}); diff --git a/tests/relay-redelivery.test.js b/tests/relay-redelivery.test.js index b9135539..d6648b57 100644 --- a/tests/relay-redelivery.test.js +++ b/tests/relay-redelivery.test.js @@ -12,8 +12,8 @@ require('./_isolate-home'); // redirect $HOME before lib/config loads * connection stays up — is held for that peer's key and offered again, sealed afresh, to the next * session proving that key; until a socket has written it, it is listed in pendingDeliveries(). * - * These tests stay under the receiver's own record budget (8 a second, burst 32): past it the - * receiver drops records unevaluated, which is a separate loss (reported, not changed here). + * These tests stay under the receiver's own record budget (8 a second, burst 32). Past it the + * receiver queues records and the sender paces to it (flow control, 0.14.3): tests/flow-control.test.js. */ const { describe, it } = require('node:test'); @@ -176,7 +176,7 @@ describe('records the relay pacer never wrote are held and offered again (R3-4)' } finally { n._running = false; n._dropRedelivery('test'); await n.stop(); fs.rmSync(nodeDirById(n.nodeId), { recursive: true, force: true }); } }); - it('the held list is bounded: past the bound the oldest is dropped and said undelivered', () => { + it('the held list is bounded: past the bound a record is not held and is said undelivered; nothing held is pushed out', () => { const n = new SymNode({ name: uniq('rd-bound'), silent: true, discovery: new NullDiscovery() }); const said = []; n.on('metric', (m) => { if (m.type === 'cmb-undelivered') said.push(m); }); @@ -189,8 +189,9 @@ describe('records the relay pacer never wrote are held and offered again (R3-4)' n._running = false; const held = n.pendingDeliveries(); assert.strictEqual(held.length, 2048, 'at most 2048 a peer'); - assert.strictEqual(held[0].key, 'cmb-2', 'the oldest went first'); - assert.deepStrictEqual(said.map((m) => [m.key, m.reason]), [['cmb-0', 'redelivery-overflow'], ['cmb-1', 'redelivery-overflow']]); + assert.strictEqual(held[0].key, 'cmb-0', 'what was held stays held (flow control, 0.14.3: a held record is never pushed out)'); + assert.deepStrictEqual(said.map((m) => [m.key, m.reason]), [['cmb-2048', 'held-full'], ['cmb-2049', 'held-full']]); + assert.deepStrictEqual(n.undelivered().map((u) => u.key), ['cmb-2048', 'cmb-2049'], 'and listed as undelivered'); } finally { n.stop(); fs.rmSync(nodeDirById(n.nodeId), { recursive: true, force: true }); } }); }); diff --git a/tests/security-0.14.3.test.js b/tests/security-0.14.3.test.js index b002015a..2cbff37b 100644 --- a/tests/security-0.14.3.test.js +++ b/tests/security-0.14.3.test.js @@ -187,25 +187,36 @@ describe('R2-3: one admitted peer cannot buy CPU, memory or disk without bound', it('R2-3: the record and verification budgets are charged by size: two of the largest records pass, a third waits', () => { const fh = new FrameHandler({ _log: () => {} }, {}); + const now = Date.now(); + // A record is admitted only when both lanes hold it (flow control, 0.14.3: otherwise it waits). + const admit = (session, chars) => { + if (fh._admitWait(session, chars, now) > 0) return false; + fh._spendVerify(session, chars, now); + fh._spendRecord(session, chars, now); + return true; + }; const session = {}; const largest = 720 * 1024; - const r = [0, 1, 2].map(() => fh._recordBudget(session, largest)); + const r = [0, 1, 2].map(() => admit(session, largest)); assert.deepStrictEqual(r, [true, true, false], 'the record lane spends the size'); const small = {}; - for (let i = 0; i < 32; i++) assert.strictEqual(fh._recordBudget(small, 2048), true, 'small records are counted by number as before'); + for (let i = 0; i < 32; i++) assert.strictEqual(admit(small, 2048), true, 'small records are counted by number as before'); + assert.strictEqual(admit(small, 2048), false, 'and the 33rd waits'); + // The verification lane (4 MiB burst) spends the size too, whatever the record lane holds. const v = {}; - let passed = 0; - for (let i = 0; i < 12; i++) if (fh._verifyBudget(v, 400 * 1024)) passed++; - assert.ok(passed >= 8 && passed <= 11, `the verification lane spends the size too (${passed} of 12 passed)`); + for (let i = 0; i < 9; i++) fh._spendVerify(v, 400 * 1024, now); + assert.strictEqual(fh._admitWait(v, 1024, now), 0, '3.6 MiB checked: the lane still holds a small record'); + for (let i = 0; i < 2; i++) fh._spendVerify(v, 400 * 1024, now); + assert.ok(fh._admitWait(v, 1024, now) > 0, '4.4 MiB checked: past the burst, even a small record waits for the lane to refill'); }); - it('R2-3: a burst of large records from one peer: only what its size budget holds reaches SVAF', async () => { + it('R2-3: a burst of large records from one peer: only what its size budget holds reaches SVAF; the rest waits', async () => { try { const node = mk('r23-flood'); if (typeof node._store.load === 'function') await node._store.load(); const mallory = identity('mallory'); const s = admitAs(node, mallory); - const over = []; node.on('metric', (m) => { if (m.type === 'cmb-over-budget' || m.type === 'cmb-over-verify-budget') over.push(m.type); }); + const over = []; node.on('metric', (m) => { if (m.type === 'cmb-queued') over.push(m.type); }); let evaluated = 0; const admit = node._frameHandler._admit; node._frameHandler._admit = (...a) => { evaluated++; return admit(...a); }; @@ -215,7 +226,7 @@ describe('R2-3: one admitted peer cannot buy CPU, memory or disk without bound', } await settle(300); assert.ok(evaluated <= 4, `at most what 1.5 MiB holds was evaluated (${evaluated})`); - assert.ok(over.length >= 8, 'the rest was dropped and counted'); + assert.ok(over.length >= 8, 'the rest waits in the session\'s queue (flow control, 0.14.3: it was dropped), counted'); } finally { await stopAll(); } });