Skip to content

Commit 2f3dd85

Browse files
wesbillmanBrainCarl
authored
fix(relay): reject a frame on its own acknowledgement channel (#6961)
Pinky, an AI agent, updated this description on Wes's behalf after taking over the startup investigation. **Category:** fix **User Impact:** An EVENT refused by WebSocket admission or handler saturation receives a correlated `OK(event_id, false, reason)` instead of an uncorrelated NOTICE, so the client can settle that refusal without waiting for its publish timeout. Rate-limited refusals also arm client backoff. This fixes a protocol failure mechanism; it does not establish that every startup send will succeed or that the reported Desktop startup incident is fully resolved. **Problem:** Startup opens several live subscriptions and publishes at once, and the relay's WebSocket admission gate is a fixed 5-second window (`ws_admission_budget` = `human_ws_events_per_sec * 5`). If that shared per-principal quota is exhausted, `enforce_ws_admission` previously rejected an EVENT with a bare `["NOTICE", reason]`. Quota pressure is a possible trigger, not proof of the original incident's complete cause. A NOTICE carries no event id. Both clients settle a pending publish *only* from an `OK` keyed by event id (desktop `pendingEvents`, mobile `_pendingEvents`), so nothing settled — and `handle_text_message` returns early, so no `OK` ever followed either. The send **could not fail**; it could only time out at `PUBLISH_TIMEOUT_MS` = 25s. That explains how this rejection mechanism can produce a roughly 25-second timeout; attributing the original report to it still requires the actual startup/send workflow. The handler-semaphore saturation path had the identical defect, and that one needs no quota burst to fire. **Solution:** NIP-01 gives each request type its own acknowledgement channel, and a rejection is only actionable on the same one. Reject a REQ with `CLOSED`, an EVENT with `OK(id, false, reason)`, and fall back to `NOTICE` only where no per-request correlation exists. COUNT refusals now also use `CLOSED(query_id, reason)` per NIP-45, covering both quota admission and handler saturation (added in `cd12c93804b87a24b61075dfd171dc471a0a527f`). Reason strings are unchanged, so the `rate-limited:` prefix and `retry in {N}s` hint that existing client gates parse keep working (desktop `parseRateLimitHint`, mobile `RelayRateLimitGate`, buzz-acp `set_rate_limit_gate`). Only the frame *type* changes, so `docs/multi-tenant-relay.md` L7 stays satisfied. Two notes on how this landed, both worth a reviewer's attention: 1. **A survived mutation became a design change.** `send_admission_result` originally took a `RejectionTarget` parameter, and reverting the *second* call site (the per-minute message quota) survived the whole suite — with Redis unreachable the first quota check short-circuits, so that line is unreachable in test. Rather than test around it, the parameter is gone: the target is derived from the frame, so no call site can name the wrong channel. 2. **The relay fix would have caused a client regression on its own.** Gate arming lived only in the NOTICE branch. Once rejections arrive as `OK:false`, `handleOk` failed the send without ever backing off — the client would retry straight into the same quota. Desktop and Mobile now arm on a `rate-limited:` OK rejection. ACP was subsequently fixed in `3b06dd32493596ec650f20abf8805791c50fdc24`: it arms the gate and re-parks only the refused observer frame, preserving other in-flight frames. Desktop gets `activateRateLimitIfSignalled` as the single owner of that prefix test, called from both `handleOk` and the NOTICE branch. <details> <summary>File changes</summary> **crates/buzz-relay/src/rejection.rs** (new) Owns the admission-rejection concern: `RejectionTarget`, `rejection_target_for`, `request_rejection_message`, `send_admission_result`, and `enforce_ws_admission`, moved out of `connection.rs`. Six tests, two of which drive the real `enforce_ws_admission` against a real `AppState`. **crates/buzz-relay/src/connection.rs** Fix the EVENT handler-semaphore rejection to correlate to the event id; delegate admission to the new module. Add two tests that drive the real `handle_text_message` with every handler permit held. Down from 1319 to 1116 lines. **crates/buzz-relay/src/state.rs** Widen the existing `test_state` helper to `pub(crate)` so the rejection tests reuse it rather than adding a ninth copy of `AppState` construction. **desktop/src/shared/api/relayRateLimitGate.ts** Add `activateRateLimitIfSignalled` — one owner for the `rate-limited:` prefix test, since three inbound frame types now carry it. **desktop/src/shared/api/relayClientSession.ts** Arm the gate on a rate-limited OK rejection; route the NOTICE branch through the same helper. Net zero lines, which keeps this already-oversized file within the differential ratchet. **desktop/src/shared/api/relayClientPublishRejection.test.mjs** (new) Four tests against the real `RelayClient`: a rate-limited OK settles the pending publish and arms the gate; an ordinary rejection does not arm it; an accepted OK still resolves. **mobile/lib/shared/relay/relay_session.dart** Arm the gate in `_handleOk` for a rate-limited rejection. **mobile/test/shared/relay/relay_session_test.dart** Two tests driving the real `publish` + `debugHandleMessage` path. </details> <details> <summary>Validation</summary> **Mutation-tested — 5 mutations, all now killed.** Each production call site was reverted to the defective behaviour to confirm a test fails. This caught two false-negative tests: | # | Mutation | Result | |---|----------|--------| | 1 | `rejection_target_for`: EVENT → `Connection` | 4 tests fail | | 2 | EVENT handler-semaphore call site → bare NOTICE | **survived at first** | | 3 | per-minute quota call site → `Connection` | **survived**; fixed by removing the parameter | | 4 | desktop `handleOk` gate arming removed | 1 test fails | | 5 | mobile `_handleOk` gate arming removed | 1 test fails | Mutation 2 is the lesson: my first saturation test called `request_rejection_message` directly, so reverting the real call site inside the `match` arm left it green. It now drives `handle_text_message` itself and dies on that mutation. - `cargo test -p buzz-relay` — 928 passed, 1 failed: `api::mesh_demo::tests::demo_join_forwarded_arm_round_trips_echo`, **pre-existing**, reproduced with all changes stashed at `4dd4d73de`. - `cd desktop && npm test` — 5721 passed, 0 failed (full suite). - `cd mobile && flutter test` — 1876 passed, 0 failed (full suite). - `just fmt-check`, `just clippy`, `just desktop-check`, `just mobile-check`, `just file-size-check` — clean. Desktop's 5 biome warnings are pre-existing (reproduced with changes stashed). - All 9 pre-push lanes green, including `rust-tests` and `desktop-tauri-checks`. **Not verified:** not reproduced end-to-end against a live relay under a forced quota burst. The causal chain is source-proven and mutation-proven at the frame level; the ~25s attribution follows from `PUBLISH_TIMEOUT_MS` but is not directly measured. A packaged-build click-through would close that gap. </details> Related work: #6957 bounds Desktop HTTP event submission, but safe retained-operation recovery after exhausted/ambiguous outcomes remains unfinished. #6998 is the separately reviewable Desktop readiness/duplicate-subscription slice. Neither is claimed to complete native before/after startup-send validation. Diagnosis note: `RESEARCH/DESKTOP_STARTUP_SEND_STALL_2026_08_27.md` (Brain's workspace). ## Current review disposition (2026-08-28) The [review on `cd12c938`](#6961 (review)) identified ACP's missing rate-limited-OK handling. Commit `3b06dd32493596ec650f20abf8805791c50fdc24` fixes gate arming, re-parking the specifically refused observer frame, and the stale NOTICE comment. Two regressions drive the real frame dispatcher. See [the implementation and validation response](#6961 (comment)). The Mobile generation-check inline thread is resolved: its `async publish` returns a failed Future when superseded; it does not throw synchronously at invocation. No further production change was indicated by that comment. The validation counts above describe the original slice, not a new rerun. At `3b06dd324`, the current GitHub check rollup has successful completed test/build checks (non-applicable jobs skipped). The security-review comment still requires review for the current base/head range; do not read a green authorization job as a completed security review. Approval and merge remain human decisions. --------- Signed-off-by: Brain <1a02c72794dcd0f07058a353bc3a81f4028b8c77c92c87fce6d5c8b85970a20b@buzz.block.builderlab.xyz> Signed-off-by: Wes <wesbillman@users.noreply.github.com> Co-authored-by: Brain <1a02c72794dcd0f07058a353bc3a81f4028b8c77c92c87fce6d5c8b85970a20b@buzz.block.builderlab.xyz> Co-authored-by: Carl <9d00794d3df50972eb8b615511783cab12a77a8fd5dd5edd58073ec73b54bd8b@buzz.block.builderlab.xyz>
1 parent 93237b4 commit 2f3dd85

13 files changed

Lines changed: 1439 additions & 166 deletions

File tree

crates/buzz-acp/src/relay.rs

Lines changed: 202 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1370,6 +1370,40 @@ impl BgState {
13701370
while let Some(event) = self.observer_in_flight.pop_back() {
13711371
self.gated_observer_pending.push_front(event);
13721372
}
1373+
self.trim_gated_observer_pending();
1374+
}
1375+
1376+
/// Re-park a frame the relay explicitly refused, ahead of frames parked
1377+
/// after the gate armed.
1378+
///
1379+
/// An `OK(id, false, …)` names the refused frame, so only that frame is
1380+
/// retried — frames still awaiting their own verdict stay in the
1381+
/// acknowledgment window. This is the correlated counterpart to
1382+
/// [`Self::requeue_observer_in_flight`], which must retry everything
1383+
/// because a NOTICE identifies nothing.
1384+
fn requeue_rejected_observer_frame(&mut self, event_id: &str) {
1385+
let Some(index) = self
1386+
.observer_in_flight
1387+
.iter()
1388+
.position(|event| event.id.to_hex() == event_id)
1389+
else {
1390+
return;
1391+
};
1392+
if let Some(event) = self.observer_in_flight.remove(index) {
1393+
if self.gated_observer_pending.len() >= GATED_OBSERVER_QUEUE_CAP {
1394+
self.gated_observer_pending.pop_front();
1395+
self.gated_observer_dropped += 1;
1396+
warn!(
1397+
dropped_total = self.gated_observer_dropped,
1398+
"gated observer queue full — dropped oldest parked frame for refused retry"
1399+
);
1400+
}
1401+
self.gated_observer_pending.push_front(event);
1402+
}
1403+
}
1404+
1405+
/// Enforce the parked-queue bound, counting evictions so loss stays visible.
1406+
fn trim_gated_observer_pending(&mut self) {
13731407
while self.gated_observer_pending.len() > GATED_OBSERVER_QUEUE_CAP {
13741408
self.gated_observer_pending.pop_front();
13751409
self.gated_observer_dropped += 1;
@@ -2362,7 +2396,10 @@ async fn handle_ws_message(
23622396
RelayMessage::Notice { message } => {
23632397
// Fix 4: NOTICE at warn level.
23642398
tracing::warn!("relay NOTICE: {message}");
2365-
// The relay sends NOTICE for rate-limited EVENT/COUNT frames.
2399+
// NOTICE now carries only connection-scoped refusals: an
2400+
// EVENT is refused via OK and a REQ/COUNT via CLOSED. A
2401+
// NOTICE names nothing, so every unacknowledged observer
2402+
// write must be retried.
23662403
if message.starts_with("rate-limited:") {
23672404
let secs = parse_rate_limit_retry_secs(&message).unwrap_or(0);
23682405
let deadline = state.set_rate_limit_gate(secs);
@@ -2530,6 +2567,25 @@ async fn handle_ws_message(
25302567
warn!("mid-session AUTH rejected (event {event_id}): {message} — triggering reconnect");
25312568
return false;
25322569
}
2570+
// A refused EVENT is acknowledged on its own channel, so the
2571+
// backoff must arm here — not only in the NOTICE arm. Without
2572+
// this the harness would publish straight back into the same
2573+
// quota it was just refused on.
2574+
if !accepted && message.starts_with("rate-limited:") {
2575+
let secs = parse_rate_limit_retry_secs(&message).unwrap_or(0);
2576+
let deadline = state.set_rate_limit_gate(secs);
2577+
// The OK names the refused frame, so re-park only that
2578+
// one rather than every unacknowledged frame.
2579+
state.requeue_rejected_observer_frame(&event_id);
2580+
warn!(
2581+
"rate-limit gate armed via OK for event {event_id} until ~{:.1}s from now",
2582+
deadline
2583+
.checked_duration_since(tokio::time::Instant::now())
2584+
.unwrap_or_default()
2585+
.as_secs_f64()
2586+
);
2587+
return true;
2588+
}
25332589
state.acknowledge_observer_frame(&event_id);
25342590
debug!("OK for event {event_id}: accepted={accepted} message={message}");
25352591
}
@@ -6136,6 +6192,151 @@ mod tests {
61366192
);
61376193
}
61386194

6195+
/// A rate-limited `OK(id, false, …)` must arm the backoff gate and re-park
6196+
/// the refused frame, driven through the real frame dispatcher.
6197+
///
6198+
/// This is the buzz-acp side of the relay's rejection-correlation change:
6199+
/// a refused EVENT is now acknowledged on its own channel instead of via
6200+
/// NOTICE. Reverting either the gate arming or the requeue in the `Ok` arm
6201+
/// must fail this test.
6202+
#[tokio::test]
6203+
async fn rate_limited_ok_arms_gate_and_reparks_refused_observer_frame() {
6204+
let (mut client, _server) = test_ws_pair().await;
6205+
let (event_tx, _event_rx) = mpsc::channel::<Option<BuzzEvent>>(4);
6206+
let (observer_control_tx, _observer_control_rx) = mpsc::channel::<Event>(4);
6207+
let keys = Keys::generate();
6208+
let mut state = BgState::new();
6209+
6210+
let refused = make_observer_frame(&keys);
6211+
let still_pending = make_observer_frame(&keys);
6212+
state.track_observer_in_flight(Box::new(refused.clone()));
6213+
state.track_observer_in_flight(Box::new(still_pending.clone()));
6214+
assert!(
6215+
state.check_rate_gate().is_none(),
6216+
"gate must start disarmed"
6217+
);
6218+
6219+
let frame = json!([
6220+
"OK",
6221+
refused.id.to_hex(),
6222+
false,
6223+
"rate-limited: retry in 5s"
6224+
]);
6225+
let should_continue = handle_ws_message(
6226+
Message::Text(frame.to_string().into()),
6227+
&mut client,
6228+
&event_tx,
6229+
&observer_control_tx,
6230+
&mut state,
6231+
&keys,
6232+
"wss://relay.test",
6233+
"agent-pubkey",
6234+
None,
6235+
)
6236+
.await;
6237+
6238+
assert!(should_continue, "a rate-limited OK must keep the socket");
6239+
assert!(
6240+
state.check_rate_gate().is_some(),
6241+
"a rate-limited OK must arm the backoff gate, or the harness \
6242+
republishes straight into the same quota"
6243+
);
6244+
let parked: Vec<_> = state
6245+
.gated_observer_pending
6246+
.iter()
6247+
.map(|event| event.id)
6248+
.collect();
6249+
assert_eq!(
6250+
parked,
6251+
[refused.id],
6252+
"the refused frame must be re-parked for redelivery, not dropped"
6253+
);
6254+
let in_flight: Vec<_> = state
6255+
.observer_in_flight
6256+
.iter()
6257+
.map(|event| event.id)
6258+
.collect();
6259+
assert_eq!(
6260+
in_flight,
6261+
[still_pending.id],
6262+
"frames still awaiting their own verdict must stay in flight"
6263+
);
6264+
}
6265+
6266+
#[test]
6267+
fn rejected_observer_frame_displaces_oldest_parked_frame_at_capacity() {
6268+
let mut state = BgState::new();
6269+
let keys = Keys::generate();
6270+
let refused = make_observer_frame(&keys);
6271+
state.track_observer_in_flight(Box::new(refused.clone()));
6272+
6273+
let oldest = make_observer_frame(&keys);
6274+
state.park_gated_observer_frame(Box::new(oldest.clone()));
6275+
let mut survivors = Vec::with_capacity(GATED_OBSERVER_QUEUE_CAP - 1);
6276+
for _ in 1..GATED_OBSERVER_QUEUE_CAP {
6277+
let event = make_observer_frame(&keys);
6278+
survivors.push(event.id);
6279+
state.park_gated_observer_frame(Box::new(event));
6280+
}
6281+
6282+
state.requeue_rejected_observer_frame(&refused.id.to_hex());
6283+
6284+
let parked: Vec<_> = state
6285+
.gated_observer_pending
6286+
.iter()
6287+
.map(|event| event.id)
6288+
.collect();
6289+
assert_eq!(parked.len(), GATED_OBSERVER_QUEUE_CAP);
6290+
assert_eq!(parked.first(), Some(&refused.id));
6291+
assert_eq!(&parked[1..], survivors.as_slice());
6292+
assert!(!parked.contains(&oldest.id));
6293+
assert_eq!(state.gated_observer_dropped, 1);
6294+
assert!(state.observer_in_flight.is_empty());
6295+
}
6296+
6297+
/// A non-rate-limit refusal is terminal: retrying would be refused
6298+
/// identically, so the frame is retired rather than re-parked, and the
6299+
/// backoff gate stays disarmed.
6300+
#[tokio::test]
6301+
async fn non_rate_limited_ok_rejection_retires_frame_without_arming_gate() {
6302+
let (mut client, _server) = test_ws_pair().await;
6303+
let (event_tx, _event_rx) = mpsc::channel::<Option<BuzzEvent>>(4);
6304+
let (observer_control_tx, _observer_control_rx) = mpsc::channel::<Event>(4);
6305+
let keys = Keys::generate();
6306+
let mut state = BgState::new();
6307+
6308+
let refused = make_observer_frame(&keys);
6309+
state.track_observer_in_flight(Box::new(refused.clone()));
6310+
6311+
let frame = json!(["OK", refused.id.to_hex(), false, "invalid: bad signature"]);
6312+
let should_continue = handle_ws_message(
6313+
Message::Text(frame.to_string().into()),
6314+
&mut client,
6315+
&event_tx,
6316+
&observer_control_tx,
6317+
&mut state,
6318+
&keys,
6319+
"wss://relay.test",
6320+
"agent-pubkey",
6321+
None,
6322+
)
6323+
.await;
6324+
6325+
assert!(should_continue, "a rejected event must not drop the socket");
6326+
assert!(
6327+
state.check_rate_gate().is_none(),
6328+
"only a rate-limit refusal arms the backoff gate"
6329+
);
6330+
assert!(
6331+
state.gated_observer_pending.is_empty(),
6332+
"a permanently refused frame must not be requeued into a retry loop"
6333+
);
6334+
assert!(
6335+
state.observer_in_flight.is_empty(),
6336+
"a permanently refused frame must be retired from the window"
6337+
);
6338+
}
6339+
61396340
/// Build a signed observer telemetry frame (kind 24200) for gate tests.
61406341
fn make_observer_frame(keys: &Keys) -> Event {
61416342
let recipient = Keys::generate();

0 commit comments

Comments
 (0)