From 65993e3fa2ac1814b28e03a9ff22af47631e18f4 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:37:51 +0200 Subject: [PATCH 01/13] feat(broker): repair node delivery diagnostics on current main Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- CHANGELOG.md | 4 + crates/broker/src/lib.rs | 1 + crates/broker/src/listen_api.rs | 137 ++ crates/broker/src/node_control.rs | 733 +++++++++- crates/broker/src/node_delivery_probe.rs | 1254 +++++++++++++++++ crates/broker/src/runtime/event_loop.rs | 5 + crates/broker/src/runtime/fleet.rs | 83 +- crates/broker/src/runtime/init.rs | 6 + crates/broker/src/runtime/tests.rs | 130 ++ packages/harness-driver/src/protocol.ts | 127 ++ .../case.json | 21 + .../1678-node-delivery-introspection/run.mjs | 487 +++++++ tests/relayflows/shared/relaycast-engine.mjs | 120 ++ 13 files changed, 3052 insertions(+), 56 deletions(-) create mode 100644 crates/broker/src/node_delivery_probe.rs create mode 100644 tests/relayflows/cases/1678-node-delivery-introspection/case.json create mode 100644 tests/relayflows/cases/1678-node-delivery-introspection/run.mjs create mode 100644 tests/relayflows/shared/relaycast-engine.mjs diff --git a/CHANGELOG.md b/CHANGELOG.md index a4ef197bae..0215839418 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -90,6 +90,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [11.10.4] - 2026-09-08 +### Added + +- Broker `GET /api/node-delivery` reports whether node-control `deliver` frames are reaching an agent, what the delivery book decided about each one, where it ended up, and whether the resulting `delivery_ack` actually left the broker, so a deaf agent can be told from a quiet one without restarting the broker. + ### Changed - `agent-relay fleet spawn --sandbox` now requests Cloud's long-running workload profile and reports the provider Cloud actually selected, enabling Agent37 placement without a provider flag. diff --git a/crates/broker/src/lib.rs b/crates/broker/src/lib.rs index 46b75fcd6c..76ca5ca7b2 100644 --- a/crates/broker/src/lib.rs +++ b/crates/broker/src/lib.rs @@ -27,6 +27,7 @@ pub(crate) mod listen_api; #[allow(dead_code)] pub(crate) mod metrics; pub(crate) mod node_control; +pub(crate) mod node_delivery_probe; #[allow(dead_code)] pub(crate) mod obligation; pub(crate) mod priorities; diff --git a/crates/broker/src/listen_api.rs b/crates/broker/src/listen_api.rs index 74f9c2aa09..e10f0051c0 100644 --- a/crates/broker/src/listen_api.rs +++ b/crates/broker/src/listen_api.rs @@ -391,6 +391,10 @@ struct ListenApiState { node_token: std::sync::Arc>>, /// Whether the broker is in persist mode persist: bool, + /// Node-control inbound introspection. Held directly (rather than reached + /// through `tx`) so `GET /api/node-delivery` answers even when the runtime + /// event loop is wedged — the case the endpoint exists to diagnose. + node_delivery_probe: std::sync::Arc, /// When the broker started started_at: std::time::Instant, input_serializers: PtyInputSerializers, @@ -427,6 +431,9 @@ pub struct ListenApiConfig { pub node_name: String, pub node_token: std::sync::Arc>>, pub persist: bool, + /// Node-control inbound introspection, read directly by + /// `GET /api/node-delivery`. See [`crate::node_delivery_probe`]. + pub node_delivery_probe: std::sync::Arc, } pub fn listen_api_router(config: ListenApiConfig) -> axum::Router { @@ -469,6 +476,7 @@ fn listen_api_router_with_auth( node_name: config.node_name, node_token: config.node_token, persist: config.persist, + node_delivery_probe: config.node_delivery_probe, started_at: std::time::Instant::now(), input_serializers: Arc::new(tokio::sync::Mutex::new(HashMap::new())), }; @@ -541,6 +549,7 @@ fn listen_api_router_with_auth( "/api/crash-insights", routing::get(listen_api_crash_insights), ) + .route("/api/node-delivery", routing::get(listen_api_node_delivery)) .route("/api/dead-letters", routing::get(listen_api_dead_letters)) .route( "/api/dead-letters/redeliver", @@ -2755,6 +2764,30 @@ async fn listen_api_crash_insights( } } +/// `GET /api/node-delivery` — introspection for the node-control inbound path. +/// +/// Deliberately answered straight from the shared probe rather than by posting +/// a [`ListenApiRequest`] to the runtime. Every other route here round-trips +/// through the event loop, but a wedged event loop is one of the conditions +/// that makes an agent go silent, and a diagnostic that hangs in exactly the +/// case it was built for is worthless. When the loop is stuck, the frame +/// counters keep climbing while `cursors_published_at_ms` stops advancing. +async fn listen_api_node_delivery( + axum::extract::State(state): axum::extract::State, +) -> (axum::http::StatusCode, axum::Json) { + let token_present = state + .node_token + .read() + .map(|token| token.is_some()) + .unwrap_or(false); + // `connected` is reported by the probe's own connect/disconnect counters + // rather than the runtime's flag, for the same no-round-trip reason. + ( + axum::http::StatusCode::OK, + axum::Json(state.node_delivery_probe.snapshot_with_token(token_present)), + ) +} + async fn listen_api_dead_letters( axum::extract::State(state): axum::extract::State, ) -> (axum::http::StatusCode, axum::Json) { @@ -3907,9 +3940,33 @@ mod auth_tests { broker_api_key: Option<&str>, local_only: bool, ) -> (axum::Router, mpsc::Receiver) { + let (router, rx, _) = test_router_with_probe_mode(broker_api_key, local_only); + (router, rx) + } + + fn test_router_with_probe( + broker_api_key: Option<&str>, + ) -> ( + axum::Router, + mpsc::Receiver, + std::sync::Arc, + ) { + test_router_with_probe_mode(broker_api_key, false) + } + + fn test_router_with_probe_mode( + broker_api_key: Option<&str>, + local_only: bool, + ) -> ( + axum::Router, + mpsc::Receiver, + std::sync::Arc, + ) { let (tx, rx) = mpsc::channel(8); let (events_tx, _events_rx) = broadcast::channel(8); let replay_buffer = ReplayBuffer::new(DEFAULT_REPLAY_CAPACITY); + let node_delivery_probe = + std::sync::Arc::new(crate::node_delivery_probe::NodeDeliveryProbe::new()); ( listen_api_router_with_auth( ListenApiConfig { @@ -3925,13 +3982,93 @@ mod auth_tests { node_name: "test-node".to_string(), node_token: std::sync::Arc::new(std::sync::RwLock::new(None)), persist: false, + node_delivery_probe: node_delivery_probe.clone(), }, broker_api_key.map(ToString::to_string), ), rx, + node_delivery_probe, ) } + /// The report names every agent on the broker and their delivery cursors. + /// That is operational detail, not public data, so the route must sit + /// behind the same API-key gate as the rest of `/api/*` — only `/health` + /// and `/api/agent-result` are unauthenticated. + #[tokio::test] + async fn node_delivery_route_requires_the_api_key_when_auth_is_enabled() { + let (router, _rx, _probe) = test_router_with_probe(Some("secret")); + let response = router + .oneshot( + Request::builder() + .uri("/api/node-delivery") + .body(Body::empty()) + .expect("request should build"), + ) + .await + .expect("router should answer"); + assert_eq!(response.status(), StatusCode::UNAUTHORIZED); + } + + /// The endpoint must report what the probe recorded, and — critically — + /// must do so WITHOUT posting a request to the runtime. A wedged runtime + /// event loop is one of the conditions that makes an agent go deaf, so a + /// diagnostic that round-trips through it would hang in exactly the case + /// it exists to diagnose. `rx` is left undrained here on purpose: it + /// stands in for a runtime that is not answering. + #[tokio::test] + async fn node_delivery_route_answers_without_the_runtime() { + use crate::node_delivery_probe::DeliverDisposition; + + let (router, mut rx, probe) = test_router_with_probe(None); + probe.record_connected(); + probe.record_text_frame(); + let deliver = crate::fleet_wire::Deliver { + v: crate::fleet_wire::FleetWireVersion, + agent: "worker-a".to_string(), + agent_id: "ag_1".to_string(), + delivery_id: "del_1".to_string(), + msg_id: "msg_1".to_string(), + seq: 7, + mode: crate::fleet_wire::DeliveryMode::Wait, + payload: json!({ "type": "dm.received" }), + }; + probe.record_frame(&crate::fleet_wire::RelaycastToBroker::Deliver( + deliver.clone(), + )); + probe.record_decision( + &deliver, + &crate::node_control::DeliveryDecision::Deliver { up_to_seq: 7 }, + ); + probe.record_disposition(&deliver, DeliverDisposition::Injected); + + let response = router + .oneshot( + Request::builder() + .uri("/api/node-delivery") + .body(Body::empty()) + .expect("request should build"), + ) + .await + .expect("router should answer"); + assert_eq!(response.status(), StatusCode::OK); + let body = response_json(response).await; + + assert_eq!(body["connected"], true); + assert_eq!(body["frames"]["deliver"], 1); + assert_eq!(body["socket"]["text_frames"], 1); + assert_eq!(body["recent_delivers"][0]["agent"], "worker-a"); + assert_eq!(body["recent_delivers"][0]["seq"], 7); + assert_eq!(body["recent_delivers"][0]["decision"], "deliver"); + assert_eq!(body["recent_delivers"][0]["disposition"], "injected"); + + // Nothing was asked of the runtime. + assert!( + rx.try_recv().is_err(), + "the introspection route must not depend on the runtime event loop" + ); + } + async fn response_json(response: axum::response::Response) -> Value { let body = to_bytes(response.into_body(), usize::MAX) .await diff --git a/crates/broker/src/node_control.rs b/crates/broker/src/node_control.rs index 5114831562..2ae45d3d3d 100644 --- a/crates/broker/src/node_control.rs +++ b/crates/broker/src/node_control.rs @@ -84,6 +84,11 @@ pub(crate) struct FleetControlConfig { /// treated as dead. `None` uses [`READ_IDLE_TIMEOUT`]; tests override it so /// the blackhole case can be covered without a 48-second wait. pub(crate) read_idle_timeout: Option, + /// Introspection sink for the inbound path. Frames are counted here + /// before deserialization, so a `deliver` the broker cannot parse is + /// still recorded as having arrived. `None` in tests that do not + /// assert on the probe. + pub(crate) probe: Option>, } /// Mints node tokens via `POST /v1/nodes` and maintains the workspace-scoped @@ -686,8 +691,26 @@ struct ActiveAgentBinding { authoritative: bool, } +/// Bookkeeping flag that never participates in equality. +/// +/// The book derives `PartialEq` and tests assert things like "identity +/// rejection must not mutate state" by comparing a book against a snapshot. +/// Whether a cursor publish is still pending is not part of the book's +/// identity, so it must not make those assertions pass or fail. +#[derive(Debug, Default, Clone, Eq)] +pub(crate) struct CursorDirtyFlag(bool); + +impl PartialEq for CursorDirtyFlag { + fn eq(&self, _: &Self) -> bool { + true + } +} + #[derive(Debug, Default, Clone, PartialEq, Eq)] pub(crate) struct FleetDeliveryBook { + /// Set by every mutator, cleared by the runtime once it has republished + /// the cursor snapshot. See [`FleetDeliveryBook::take_cursor_dirty`]. + dirty: CursorDirtyFlag, agents: HashMap, active_agent_bindings_by_name: HashMap, active_agent_names_by_id: HashMap, @@ -699,6 +722,7 @@ impl FleetDeliveryBook { const RETIRED_AGENT_ID_CAPACITY: usize = 512; fn forget_retired_identity(&mut self, agent_id: &str) { + self.mark_cursors_dirty(); if self.retired_agent_names_by_id.remove(agent_id).is_some() { self.retired_agent_id_order .retain(|retired_id| retired_id != agent_id); @@ -706,6 +730,7 @@ impl FleetDeliveryBook { } fn retire_identity(&mut self, agent_id: String, agent_name: String) { + self.mark_cursors_dirty(); self.forget_retired_identity(&agent_id); while self.retired_agent_id_order.len() >= Self::RETIRED_AGENT_ID_CAPACITY { if let Some(evicted) = self.retired_agent_id_order.pop_front() { @@ -729,6 +754,7 @@ impl FleetDeliveryBook { } fn bind_identity(&mut self, agent: &str, agent_id: &str, authoritative: bool) -> bool { + self.mark_cursors_dirty(); if !authoritative && self.nonauthoritative_binding_conflicts(agent, agent_id) { return false; } @@ -787,6 +813,7 @@ impl FleetDeliveryBook { agent: impl Into, agent_id: impl Into, ) { + self.mark_cursors_dirty(); let agent = agent.into(); let agent_id = agent_id.into(); self.bind_identity(&agent, &agent_id, true); @@ -815,6 +842,7 @@ impl FleetDeliveryBook { agent_id: impl Into, up_to_seq: u64, ) { + self.mark_cursors_dirty(); let agent = agent.into(); let agent_id = agent_id.into(); debug_assert!(self @@ -848,6 +876,7 @@ impl FleetDeliveryBook { deliveries: &[&Deliver], ack_floor: Option, ) { + self.mark_cursors_dirty(); let mut sequenced = deliveries .iter() .copied() @@ -1002,7 +1031,55 @@ impl FleetDeliveryBook { } } + /// Export the per-identity cursors for introspection. + /// + /// Until this existed the delivery book was entirely opaque at runtime: + /// nothing in the broker could say what sequence an agent was acked to, so + /// a silent agent could not be told apart from one whose cursor had been + /// retired underneath it. Ordered by name to keep the endpoint's output + /// stable between reads. + /// Mark the cursor snapshot stale. Called by every mutator; the runtime + /// drains this once per event-loop turn. + fn mark_cursors_dirty(&mut self) { + self.dirty.0 = true; + } + + /// Consume the pending-publish flag. + /// + /// Mirrors the `take_dirty()` used by the persisted stores so cursor + /// publication happens in exactly one place in the event loop rather than + /// at each mutation site. Publishing only from the deliver path left the + /// endpoint reporting obsolete acknowledgements and retired agents + /// whenever a worker confirmation, manual flush, registration, identity + /// rebind, or release moved the book without a later frame arriving. + pub(crate) fn take_cursor_dirty(&mut self) -> bool { + std::mem::take(&mut self.dirty.0) + } + + pub(crate) fn cursor_views(&self) -> Vec { + let mut views: Vec<_> = self + .agents + .iter() + .map( + |(agent_id, cursor)| crate::node_delivery_probe::AgentCursorView { + agent_id: agent_id.clone(), + agent_name: cursor.agent_name.clone(), + acked_up_to_seq: cursor.acked_up_to_seq, + received_up_to_seq: cursor.received_up_to_seq, + has_sequenced_position: cursor.has_sequenced_position, + }, + ) + .collect(); + views.sort_by(|a, b| { + a.agent_name + .cmp(&b.agent_name) + .then_with(|| a.agent_id.cmp(&b.agent_id)) + }); + views + } + pub(crate) fn commit_received(&mut self, deliver: &Deliver) -> u64 { + self.mark_cursors_dirty(); if !self.bind_identity(&deliver.agent, &deliver.agent_id, false) { return self.active_up_to_seq(&deliver.agent); } @@ -1043,6 +1120,7 @@ impl FleetDeliveryBook { &mut self, receipt: &RelaycastDeliveryReceipt, ) -> Option { + self.mark_cursors_dirty(); let cursor = self.agents.get_mut(receipt.agent_id.as_str())?; cursor.agent_name = receipt.agent.to_string(); if receipt.seq == 0 { @@ -1064,6 +1142,7 @@ impl FleetDeliveryBook { /// out-of-order confirmation stays held on this agent's cursor until every /// lower received sequence has also confirmed. pub(crate) fn commit_confirmed_delivery(&mut self, deliver: &Deliver) -> Option { + self.mark_cursors_dirty(); self.commit_received(deliver); let cursor = self.agents.get_mut(deliver.agent_id.as_str())?; if deliver.seq == 0 { @@ -1164,6 +1243,7 @@ impl FleetDeliveryBook { } pub(crate) fn commit_delivered(&mut self, deliver: &Deliver) -> u64 { + self.mark_cursors_dirty(); self.commit_received(deliver); let receipt = RelaycastDeliveryReceipt { agent: deliver.agent.clone().into(), @@ -1197,6 +1277,7 @@ impl FleetDeliveryBook { } pub(crate) fn remove_agent(&mut self, agent: &str) { + self.mark_cursors_dirty(); if let Some(binding) = self.active_agent_bindings_by_name.remove(agent) { self.active_agent_names_by_id.remove(&binding.agent_id); self.agents.remove(&binding.agent_id); @@ -1794,6 +1875,40 @@ fn connect_error_is_unauthorized(error: &tokio_tungstenite::tungstenite::Error) ) } +/// Records a node-control session's connect on creation and its matching +/// disconnect on drop. +/// +/// `run_connected_once` has twenty-odd `return ControlRunResult::*` paths — +/// send failures, read failures, idle timeout, shutdown, unauthorized. Asking +/// each of them to remember a `record_disconnected` guarantees one eventually +/// will not. More importantly this state must be owned by the socket task, not +/// the runtime: reporting it from `handle_fleet_control_event` means a wedged +/// event loop never processes `Disconnected`, so the endpoint keeps claiming +/// `connected: true` for a dead socket — the exact failure it exists to +/// diagnose. Drop runs on every exit path, including a panic unwind. +struct ProbeSessionGuard<'a> { + probe: Option<&'a std::sync::Arc>, +} + +impl<'a> ProbeSessionGuard<'a> { + fn enter( + probe: Option<&'a std::sync::Arc>, + ) -> Self { + if let Some(probe) = probe { + probe.record_connected(); + } + Self { probe } + } +} + +impl Drop for ProbeSessionGuard<'_> { + fn drop(&mut self) { + if let Some(probe) = self.probe { + probe.record_disconnected(); + } + } +} + async fn run_connected_once( config: &FleetControlConfig, command_rx: &mut mpsc::Receiver, @@ -1864,6 +1979,8 @@ async fn run_connected_once( return ControlRunResult::Disconnected; } }; + // Socket-owned connectivity: armed here, released by Drop on every exit. + let _probe_session = ProbeSessionGuard::enter(config.probe.as_ref()); let _ = event_tx.send(FleetControlEvent::Connected).await; let (mut sink, mut stream) = ws.split(); let mut pending_agent_registrations: HashMap = HashMap::new(); @@ -1942,7 +2059,21 @@ async fn run_connected_once( } } Some(FleetControlCommand::Send(message)) => { - if send_wire(&mut sink, &message).await.is_err() { + // A `delivery_ack` is the engine's only evidence that a + // frame was consumed. The runtime records the *decision* + // to ack before handing it here and cannot wait for the + // wire, so the probe learns the outcome at the one place + // that knows it. See `NodeDeliveryProbe::record_ack_sent`. + let is_ack = matches!(message, BrokerToRelaycast::DeliveryAck(_)); + let sent = send_wire(&mut sink, &message).await; + if let (true, Some(probe)) = (is_ack, config.probe.as_ref()) { + if sent.is_ok() { + probe.record_ack_sent(); + } else { + probe.record_ack_send_failed(); + } + } + if sent.is_err() { return ControlRunResult::Disconnected; } } @@ -2040,7 +2171,7 @@ async fn run_connected_once( // answering our ping, which is the only traffic a healthy but // idle engine is guaranteed to send. last_inbound = Instant::now(); - if !handle_server_message(message, event_tx, &mut pending_agent_registrations, &mut pending_deregistrations, &mut sink).await { + if !handle_server_message(message, event_tx, &mut pending_agent_registrations, &mut pending_deregistrations, &mut sink, config.probe.as_ref()).await { drain_agent_registrations(&mut pending_agent_registrations, "node_control_disconnected"); return ControlRunResult::Disconnected; } @@ -2082,62 +2213,90 @@ async fn handle_server_message( pending_agent_registrations: &mut HashMap, pending_deregistrations: &mut HashMap>>, sink: &mut S, + probe: Option<&std::sync::Arc>, ) -> bool where S: Sink + Unpin, S::Error: std::error::Error + Send + Sync + 'static, { match message { - Message::Text(text) => match serde_json::from_str::(&text) { - Ok(RelaycastToBroker::Reply(reply)) => { - if let Some(pending) = pending_deregistrations.remove(&reply.id) { - let result = if reply.ok { - Ok(()) - } else { - Err("agent_deregister_rejected".to_string()) - }; - let _ = pending.send(result); - return true; - } - - complete_agent_registration(reply, pending_agent_registrations, sink).await + Message::Text(text) => { + // Counted before `from_str`, deliberately. `ServerToNode` is + // `#[serde(tag = "type")]`, so a `deliver` carrying a field this + // build cannot parse fails as a whole and is dropped at the `Err` + // arm below. Counting only successfully-parsed frames would report + // "no deliver frames arrived" for a broker that is in fact + // receiving deliveries and throwing them away. + if let Some(probe) = probe { + probe.record_text_frame(); } - Ok(RelaycastToBroker::Error(error)) => { - if let Some(pending) = pending_deregistrations.remove(&error.id) { - let _ = pending.send(Err(format!("{}: {}", error.code, error.message))); - return true; + match serde_json::from_str::(&text) { + Ok(frame) => { + if let Some(probe) = probe { + probe.record_frame(&frame); + } + match frame { + RelaycastToBroker::Reply(reply) => { + if let Some(pending) = pending_deregistrations.remove(&reply.id) { + let result = if reply.ok { + Ok(()) + } else { + Err("agent_deregister_rejected".to_string()) + }; + let _ = pending.send(result); + return true; + } + complete_agent_registration(reply, pending_agent_registrations, sink) + .await + } + RelaycastToBroker::Error(error) => { + if let Some(pending) = pending_deregistrations.remove(&error.id) { + let _ = + pending.send(Err(format!("{}: {}", error.code, error.message))); + return true; + } + if error.code == "invalid_message" { + fail_unsupported_channel_isolation( + &error.message, + pending_agent_registrations, + ); + } + // Surface every engine rejection at error level. A node.register or + // heartbeat rejection (e.g. node_name_conflict) matches no pending + // agent registration below, so without this it vanishes silently — + // leaving the node half-registered with dead heartbeats and no signal. + tracing::error!( + target = "relay_broker::fleet", + code = %error.code, + message = %error.message, + id = %error.id, + "engine rejected a node control frame" + ); + fail_agent_registration( + &error.id, + format!("{}: {}", error.code, error.message), + pending_agent_registrations, + ); + true + } + other => event_tx + .send(FleetControlEvent::Message(other)) + .await + .is_ok(), + } } - - // Surface every engine rejection at error level. A node.register or - // heartbeat rejection (e.g. node_name_conflict) matches no pending - // agent registration below, so without this it vanishes silently — - // leaving the node half-registered with dead heartbeats and no signal. - tracing::error!( - target = "relay_broker::fleet", - code = %error.code, - message = %error.message, - id = %error.id, - "engine rejected a node control frame" - ); - if error.code == "invalid_message" { - fail_unsupported_channel_isolation(&error.message, pending_agent_registrations); + Err(error) => { + // This arm is where an unparseable `deliver` dies. With + // `RUST_LOG` unset the warning below goes nowhere, which is + // why the probe records the failure as state instead. + if let Some(probe) = probe { + probe.record_parse_failure(&error.to_string(), &text); + } + tracing::warn!(target = "relay_broker::fleet", error = %error, "invalid fleet node ws frame"); + true } - fail_agent_registration( - &error.id, - format!("{}: {}", error.code, error.message), - pending_agent_registrations, - ); - true } - Ok(other) => event_tx - .send(FleetControlEvent::Message(other)) - .await - .is_ok(), - Err(error) => { - tracing::warn!(target = "relay_broker::fleet", error = %error, "invalid fleet node ws frame"); - true - } - }, + } Message::Ping(_) => true, Message::Close(_) => false, _ => true, @@ -3347,7 +3506,8 @@ mod tests { &events, &mut pending, &mut deregistrations, - &mut sink + &mut sink, + None, ) .await ); @@ -3570,6 +3730,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, command_rx, event_tx, @@ -3695,6 +3856,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, command_rx, event_tx, @@ -3863,6 +4025,7 @@ mod tests { }), session_token: Some(session_token.clone()), read_idle_timeout: None, + probe: None, }, command_rx, event_tx, @@ -3926,6 +4089,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, command_rx, event_tx, @@ -4023,6 +4187,472 @@ mod tests { let _ = command_tx.send(FleetControlCommand::Shutdown).await; } + /// Poll the probe until `ready` holds, so tests observe state transitions + /// without sleeping on a machine whose load they do not control. + async fn wait_for_probe( + probe: &std::sync::Arc, + ready: impl Fn(&serde_json::Value) -> bool, + ) { + for _ in 0..1_000 { + if ready(&probe.snapshot_with_token(true)) { + return; + } + tokio::time::sleep(Duration::from_millis(10)).await; + } + panic!( + "probe never reached the expected state: {}", + probe.snapshot_with_token(true) + ); + } + + /// relay#1680 review (coderabbitai, fleet.rs:857) MUST-FIRE. + /// + /// The runtime stamps `surfaced_and_acked` / `acked_without_surfacing` when + /// it DECIDES to acknowledge, then hands the ack to this task over a + /// channel. It cannot await the wire, so the disposition alone reports an + /// ack the engine may never have received. This task is the only place that + /// knows, so `acks.sent` must be recorded here — and only for acks, or the + /// tally would be satisfied by unrelated traffic and could not report the + /// negative. + #[tokio::test] + async fn the_socket_task_records_which_acks_reached_the_wire() { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let ws_url = format!("ws://{}/v1/node/ws", listener.local_addr().unwrap()); + let (command_tx, mut command_rx) = mpsc::channel(4); + let (event_tx, _event_rx) = mpsc::channel(8); + let mut registration = Some(build_node_register( + &test_manifest(), + "node-test", + "host-test", + "broker/test", + None, + )); + let mut inventory = Vec::new(); + let mut load = FleetLoadSnapshot { + active_agents: 0, + max_agents: 4, + handlers_live: true, + active_agent_names: Vec::new(), + }; + let probe = std::sync::Arc::new(crate::node_delivery_probe::NodeDeliveryProbe::new()); + + // Drain whatever the client writes and never close from this side, so + // the session ends on the `Shutdown` the driver sends. + let server = tokio::spawn(async move { + let (stream, _) = listener.accept().await.unwrap(); + let mut ws = accept_async(stream).await.unwrap(); + while ws.next().await.is_some() {} + }); + + let config = FleetControlConfig { + ws_url, + node_token: Some("nt_test".to_string()), + node_id: "node-test".to_string(), + node_name: "host-test".to_string(), + broker_version: "broker/test".to_string(), + token_minter: None, + session_token: None, + read_idle_timeout: None, + probe: Some(probe.clone()), + }; + let session = run_connected_once( + &config, + &mut command_rx, + &event_tx, + &mut registration, + &mut inventory, + &mut load, + Duration::from_secs(3_600), + ); + let driver = async { + wait_for_probe(&probe, |snapshot| snapshot["socket"]["connects"] == 1).await; + command_tx + .send(FleetControlCommand::Send(delivery_ack("agent-a", 7))) + .await + .expect("ack should be accepted"); + wait_for_probe(&probe, |snapshot| snapshot["acks"]["sent"] == 1).await; + + // Traffic that is not an ack must not move the ack tally, or + // `acks.sent` could not distinguish "the engine was told" from + // "the socket was busy". + command_tx + .send(FleetControlCommand::Send(BrokerToRelaycast::ActionResult( + ActionResult { + v: FLEET_WIRE_VERSION, + id: None, + invocation_id: "inv-not-an-ack".to_string(), + result: ActionResultPayload::Output(ActionResultOutput { + output: json!({"ok": true}), + }), + }, + ))) + .await + .expect("action result should be accepted"); + command_tx + .send(FleetControlCommand::Shutdown) + .await + .expect("shutdown should be accepted"); + }; + let (result, ()) = tokio::time::timeout(Duration::from_secs(10), async { + tokio::join!(session, driver) + }) + .await + .expect("mock node-control session should finish"); + assert_eq!(result, ControlRunResult::Shutdown); + server.abort(); + + let snapshot = probe.snapshot_with_token(true); + assert_eq!( + snapshot["acks"]["sent"], 1, + "the ack reached the wire, so the probe must be able to say so" + ); + assert_eq!( + snapshot["acks"]["send_failed"], 0, + "the write succeeded; nothing should be tallied as failed" + ); + assert!( + snapshot["acks"]["last_sent_at_ms"].is_u64(), + "an ack on the wire must stamp a last-sent time" + ); + } + + /// relay#1680 review (P2), raised independently by three reviewers. + /// + /// Connectivity must be owned by the socket task, not by the runtime. When + /// it was recorded from `handle_fleet_control_event`, a wedged event loop + /// never processed `Disconnected`, so the endpoint kept reporting + /// `connected: true` for a dead socket — the exact failure it exists to + /// diagnose. The receiver is DROPPED here to stand in for a runtime that + /// will never consume another event; the probe must still track the + /// session, and must show disconnected once the session ends. + #[tokio::test] + async fn socket_owns_connectivity_when_the_runtime_never_consumes_events() { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let ws_url = format!("ws://{}/v1/node/ws", listener.local_addr().unwrap()); + let (command_tx, mut command_rx) = mpsc::channel(4); + // A runtime that is gone/wedged: nothing will ever read these. + let (event_tx, event_rx) = mpsc::channel(1); + drop(event_rx); + let mut registration = Some(build_node_register( + &test_manifest(), + "node-test", + "host-test", + "broker/test", + None, + )); + let mut inventory = Vec::new(); + let mut load = FleetLoadSnapshot { + active_agents: 0, + max_agents: 4, + handlers_live: true, + active_agent_names: Vec::new(), + }; + let probe = std::sync::Arc::new(crate::node_delivery_probe::NodeDeliveryProbe::new()); + let observed = probe.clone(); + + // The server holds the connection open and never closes it. Letting the + // peer close would race the client's own timer branches: a periodic + // write to an already-closed socket returns `Disconnected` before the + // read branch has drained anything. The test ends the session itself, + // via `Shutdown`, so the exit path is chosen rather than raced. + let server = tokio::spawn(async move { + let (stream, _) = listener.accept().await.unwrap(); + let mut ws = accept_async(stream).await.unwrap(); + // The session is established; the guard must have armed by now. + let _ = next_node_to_server(&mut ws).await; + assert_eq!( + observed.snapshot_with_token(true)["connected"], + serde_json::json!(true), + "connect must be recorded by the socket task, not the runtime" + ); + // Park until the client hangs up, without closing from this side. + while ws.next().await.is_some() {} + }); + + let config = FleetControlConfig { + ws_url, + node_token: Some("nt_test".to_string()), + node_id: "node-test".to_string(), + node_name: "host-test".to_string(), + broker_version: "broker/test".to_string(), + token_minter: None, + session_token: None, + read_idle_timeout: None, + probe: Some(probe.clone()), + }; + let session = run_connected_once( + &config, + &mut command_rx, + &event_tx, + &mut registration, + &mut inventory, + &mut load, + // Far beyond the test's lifetime: the periodic refresh must never + // fire here, or it becomes another way to exit the session. + Duration::from_secs(3_600), + ); + let driver = async { + wait_for_probe(&probe, |snapshot| snapshot["socket"]["connects"] == 1).await; + command_tx + .send(FleetControlCommand::Shutdown) + .await + .expect("shutdown should be accepted"); + }; + let (result, ()) = tokio::time::timeout(Duration::from_secs(10), async { + tokio::join!(session, driver) + }) + .await + .expect("mock node-control session should finish"); + // Exiting via Shutdown rather than a peer close also proves the guard + // releases on a non-`Disconnected` return. + assert_eq!(result, ControlRunResult::Shutdown); + server.abort(); + + let snapshot = probe.snapshot_with_token(true); + // Exactly one connect, exactly one matching disconnect, released by the + // guard's Drop on whichever return path fired. + assert_eq!(snapshot["socket"]["connects"], 1); + assert_eq!(snapshot["socket"]["disconnects"], 1); + assert_eq!( + snapshot["connected"], + serde_json::json!(false), + "a closed socket must not keep reading as connected" + ); + } + + /// relay#1680 review (P2). Publishing cursors only from the deliver path + /// left the endpoint serving an obsolete ACK indefinitely: the deferred + /// (echo-confirmed) and manual-flush ACKs advance `acked_up_to_seq` well + /// after the frame was handled. Every mutator must mark the snapshot + /// stale so the event loop republishes it. + #[test] + fn every_delivery_book_mutation_marks_the_cursor_snapshot_stale() { + fn deliver_frame(agent: &str, agent_id: &str, seq: u64) -> Deliver { + Deliver { + v: crate::fleet_wire::FleetWireVersion, + agent: agent.to_string(), + agent_id: agent_id.to_string(), + delivery_id: format!("del_{seq}"), + msg_id: format!("msg_{seq}"), + seq, + mode: DeliveryMode::Wait, + payload: serde_json::json!({ "type": "dm.received" }), + } + } + + // Each case: (name, mutation). All must leave the flag set. + type Mutation = (&'static str, Box); + let cases: Vec = vec![ + ( + "commit_received", + Box::new(|book: &mut FleetDeliveryBook| { + book.commit_received(&deliver_frame("a", "ag_a", 1)); + }), + ), + ( + "commit_delivered", + Box::new(|book: &mut FleetDeliveryBook| { + book.commit_delivered(&deliver_frame("a", "ag_a", 2)); + }), + ), + ( + // relay#1680: the deferred-ACK path that previously never + // republished, so a confirmed delivery left a stale cursor. + "commit_confirmed_delivery", + Box::new(|book: &mut FleetDeliveryBook| { + book.commit_confirmed_delivery(&deliver_frame("a", "ag_a", 3)); + }), + ), + ( + "commit_acked_receipt", + Box::new(|book: &mut FleetDeliveryBook| { + book.commit_acked_receipt(&RelaycastDeliveryReceipt { + agent: crate::ids::WorkerName::from("a"), + agent_id: crate::ids::AgentId::from("ag_a"), + delivery_id: crate::ids::DeliveryId::from("del_9"), + msg_id: crate::ids::EventId::from("msg_9"), + seq: 9, + }); + }), + ), + ( + "bind_authoritative_identity", + Box::new(|book: &mut FleetDeliveryBook| { + book.bind_authoritative_identity("a", "ag_a"); + }), + ), + ( + // `seed_cursor` asserts the name is already bound, so bind + // first and re-clear the flag to isolate the seed itself. + "seed_cursor", + Box::new(|book: &mut FleetDeliveryBook| { + book.bind_authoritative_identity("a", "ag_a"); + book.take_cursor_dirty(); + book.seed_cursor("a", "ag_a", 4); + }), + ), + ( + "restore_pending_agent", + Box::new(|book: &mut FleetDeliveryBook| { + let frame = deliver_frame("a", "ag_a", 5); + book.restore_pending_agent(&[&frame], Some(4)); + }), + ), + ( + "remove_agent", + Box::new(|book: &mut FleetDeliveryBook| { + book.remove_agent("a"); + }), + ), + ]; + + for (name, mutate) in cases { + let mut book = FleetDeliveryBook::default(); + // Clear whatever setup left behind, then mutate. + book.take_cursor_dirty(); + mutate(&mut book); + assert!( + book.take_cursor_dirty(), + "{name} must mark the cursor snapshot stale so the event loop republishes it" + ); + // Draining is one-shot: a second take must report clean. + assert!(!book.take_cursor_dirty(), "{name} left the flag set twice"); + } + } + + /// The instrument's headline claim: a `deliver` frame the broker cannot + /// deserialize is still reported as having ARRIVED. That property lives in + /// the ORDER of two statements in `handle_server_message` — count, then + /// parse — so it cannot be locked by calling the probe's methods directly. + /// This drives a real node-control session and asserts it at the call site. + #[tokio::test] + async fn probe_counts_an_unparseable_deliver_as_arrived() { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let ws_url = format!("ws://{}/v1/node/ws", listener.local_addr().unwrap()); + let (command_tx, mut command_rx) = mpsc::channel(4); + let (event_tx, mut event_rx) = mpsc::channel(8); + let mut registration = Some(build_node_register( + &test_manifest(), + "node-test", + "host-test", + "broker/test", + None, + )); + let mut inventory = Vec::new(); + let mut load = FleetLoadSnapshot { + active_agents: 0, + max_agents: 4, + handlers_live: true, + active_agent_names: Vec::new(), + }; + let probe = std::sync::Arc::new(crate::node_delivery_probe::NodeDeliveryProbe::new()); + + let server = tokio::spawn(async move { + let (stream, _) = listener.accept().await.unwrap(); + let mut ws = accept_async(stream).await.unwrap(); + assert!(matches!( + next_node_to_server(&mut ws).await, + BrokerToRelaycast::NodeRegister(_) + )); + + // A frame whose `type` this build does not know. `ServerToNode` is + // `#[serde(tag = "type")]`, so this fails `from_str` as a whole. + ws.send(Message::Text( + r#"{"type":"deliver.v2","agent":"worker-a","seq":9}"#.into(), + )) + .await + .unwrap(); + + // And one the broker does understand, so the test distinguishes + // "counted everything" from "counted nothing but the failure". + ws.send(Message::Text( + serde_json::to_string(&RelaycastToBroker::Deliver(Deliver { + v: crate::fleet_wire::FleetWireVersion, + agent: "worker-a".to_string(), + agent_id: "ag_1".to_string(), + delivery_id: "del_1".to_string(), + msg_id: "msg_1".to_string(), + seq: 1, + mode: DeliveryMode::Wait, + payload: serde_json::json!({ "type": "dm.received" }), + })) + .unwrap(), + )) + .await + .unwrap(); + + // Park without closing: a peer close races the client's timer + // branches, which can exit the session before the frames above are + // drained. The test ends it deterministically via `Shutdown`. + while ws.next().await.is_some() {} + }); + + let config = FleetControlConfig { + ws_url, + node_token: Some("nt_test".to_string()), + node_id: "node-test".to_string(), + node_name: "host-test".to_string(), + broker_version: "broker/test".to_string(), + token_minter: None, + session_token: None, + read_idle_timeout: None, + probe: Some(probe.clone()), + }; + let session = run_connected_once( + &config, + &mut command_rx, + &event_tx, + &mut registration, + &mut inventory, + &mut load, + Duration::from_secs(3_600), + ); + let driver = async { + // Both frames counted -> the client has drained the read side. + wait_for_probe(&probe, |snapshot| snapshot["socket"]["text_frames"] == 2).await; + command_tx + .send(FleetControlCommand::Shutdown) + .await + .expect("shutdown should be accepted"); + }; + let (result, ()) = tokio::time::timeout(Duration::from_secs(10), async { + tokio::join!(session, driver) + }) + .await + .expect("mock node-control session should finish"); + assert_eq!(result, ControlRunResult::Shutdown); + server.abort(); + + let snapshot = probe.snapshot_with_token(true); + // BOTH frames are counted as arrived, including the one that could not + // be parsed. If the count moved after the parse, this would read 1. + assert_eq!( + snapshot["socket"]["text_frames"], 2, + "an unparseable frame must still count as having arrived: {snapshot}" + ); + assert_eq!(snapshot["socket"]["parse_failures"], 1); + assert_eq!(snapshot["unparsed_frame_types"]["deliver.v2"], 1); + // Only the parseable one reaches the deliver counter and the runtime. + assert_eq!(snapshot["frames"]["deliver"], 1); + // The session also emits `Connected`, so drain rather than assuming the + // deliver is first in the queue. + let mut forwarded = Vec::new(); + while let Ok(event) = event_rx.try_recv() { + forwarded.push(event); + } + assert_eq!( + forwarded + .iter() + .filter(|event| matches!( + event, + FleetControlEvent::Message(RelaycastToBroker::Deliver(_)) + )) + .count(), + 1, + "exactly the parseable deliver should reach the runtime: {forwarded:?}" + ); + } + #[tokio::test] async fn connected_node_refreshes_idle_agent_inventory_before_presence_expires() { let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); @@ -4093,6 +4723,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, &mut command_rx, &event_tx, @@ -4171,6 +4802,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, &mut command_rx, &event_tx, @@ -4216,6 +4848,7 @@ mod tests { // Short window so the blackhole is covered in well under a // second; production uses READ_IDLE_TIMEOUT (48s). read_idle_timeout: Some(Duration::from_millis(400)), + probe: None, }, command_rx, event_tx, @@ -4293,6 +4926,7 @@ mod tests { // control arm under identical time pressure rather than a // separate, looser test. read_idle_timeout: Some(Duration::from_millis(400)), + probe: None, }, command_rx, event_tx, @@ -4373,6 +5007,7 @@ mod tests { token_minter: None, session_token: None, read_idle_timeout: None, + probe: None, }, command_rx, event_tx, diff --git a/crates/broker/src/node_delivery_probe.rs b/crates/broker/src/node_delivery_probe.rs new file mode 100644 index 0000000000..470a632bf3 --- /dev/null +++ b/crates/broker/src/node_delivery_probe.rs @@ -0,0 +1,1254 @@ +//! Introspection for the node-control inbound path. +//! +//! The broker's only message-delivery path is the `/v1/node/ws` node-control +//! socket: an engine `deliver` frame arrives there, is deserialized into +//! [`crate::fleet_wire::Deliver`], and is dispatched by +//! `BrokerRuntime::handle_fleet_deliver`. Until this module existed, every +//! failure along that path was observable only through `tracing`, and a broker +//! started without `RUST_LOG` emits none of it. That left the most basic +//! question about a silent agent — *did a `deliver` frame reach this broker at +//! all?* — unanswerable on a running process without restarting it, which +//! destroys the in-memory cursors that hold the evidence. +//! +//! This probe is deliberately **state, not logs**: counters and a small ring +//! buffer updated inline on the delivery path and read back over +//! `GET /api/node-delivery`. It is unaffected by `RUST_LOG`. +//! +//! Two properties are load-bearing: +//! +//! 1. **It counts before deserialization.** `ServerToNode` is +//! `#[serde(tag = "type")]`, so a `deliver` frame carrying a field the +//! broker cannot parse — or a `type` this build does not know — fails +//! `from_str` as a whole and is dropped at a `tracing::warn!`. Counting only +//! successfully-parsed frames would report "no deliver frames arrived" for a +//! broker that is in fact receiving them and throwing them away. The parse +//! failure counter and [`ProbeSnapshot::unparsed_frame_types`] distinguish +//! those two worlds. +//! +//! 2. **It is read without a runtime round trip.** The counters live behind an +//! `Arc`, so `GET /api/node-delivery` answers straight from shared state +//! rather than posting a `ListenApiRequest` to the runtime event loop. A +//! wedged event loop is itself a plausible cause of a deaf agent, and a +//! diagnostic that hangs in exactly the case it was built to diagnose is +//! worthless. When the loop is stuck, the frame counters keep climbing while +//! `cursors_published_at_ms` goes stale — which is the diagnosis. +//! +//! Nothing here records message bodies. Recent-frame entries carry identifiers, +//! sequence numbers and the payload's `type` discriminator only, so the +//! endpoint stays safe to paste into an issue. + +use std::collections::BTreeMap; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::Mutex; +use std::time::{SystemTime, UNIX_EPOCH}; + +use serde_json::{json, Value}; + +use crate::fleet_wire::{Deliver, RelaycastToBroker}; +use crate::node_control::DeliveryDecision; + +/// How many recent `deliver` frames to retain. Enough to cover a demo-sized +/// burst without letting a busy broker retain unbounded history. +const RECENT_CAPACITY: usize = 32; + +/// Cap on distinct `type` values retained for unparseable frames. A malformed +/// engine could otherwise turn this map into an unbounded allocation. +const UNPARSED_TYPE_CAPACITY: usize = 16; + +/// Cap on a retained serde error string. +const ERROR_EXCERPT_LIMIT: usize = 300; + +/// Cap on per-agent rows. A broker hosts tens of agents; this bounds the map +/// against a peer inventing names. +const AGENT_STATS_CAPACITY: usize = 256; + +/// Cap on any single peer-supplied string this probe retains. +/// +/// The slot counts above bound how *many* strings are kept; without a per-field +/// bound a peer can still multiply one oversized value across every slot — 32 +/// `RecentDeliver` rows, 16 `unparsed_frame_types` keys and 256 agent rows all +/// hold peer-chosen text. Real values are short: `payload_type` is `dm.received` +/// or `message.created`, ids are UUID-shaped, agent names are handles. 128 bytes +/// keeps every legitimate value intact while capping retained peer text at a few +/// hundred kilobytes in the worst case. +const PEER_STRING_LIMIT: usize = 128; + +fn now_ms() -> u64 { + SystemTime::now() + .duration_since(UNIX_EPOCH) + .map(|d| d.as_millis() as u64) + .unwrap_or(0) +} + +/// What `handle_fleet_deliver` ultimately did with a frame. Recorded separately +/// from the [`DeliveryDecision`] because a decision of `Deliver` still has +/// several possible ends — injected, held for a manual flush, or failed at the +/// PTY boundary — and "where did it stop" is the whole question this answers. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum DeliverDisposition { + /// Crossed the PTY injection boundary; ack withheld pending worker echo. + Injected, + /// Surfaced with nothing to verify (ambient receipt/reaction); acked now. + SurfacedAndAcked, + /// Received into the volatile FIFO, owned by Relaycast until a flush. + HeldForManualFlush, + /// Surfacing returned an error; ack withheld and the frame goes nowhere. + SurfaceFailed, + /// Recognized as duplicate/stale/gap: acked without surfacing. + AckedWithoutSurfacing, + /// Conflicting agent identity: dropped, ack withheld. + RejectedIdentity, + /// The book could not place the frame's sequence. Distinct from an + /// identity reject: the agent never saw this message and the engine still + /// owns it, so it must not be reported as the same condition. + RejectedSequenceGap, +} + +impl DeliverDisposition { + fn as_str(self) -> &'static str { + match self { + Self::Injected => "injected", + Self::SurfacedAndAcked => "surfaced_and_acked", + Self::HeldForManualFlush => "held_for_manual_flush", + Self::SurfaceFailed => "surface_failed", + Self::AckedWithoutSurfacing => "acked_without_surfacing", + Self::RejectedIdentity => "rejected_identity", + Self::RejectedSequenceGap => "rejected_sequence_gap", + } + } +} + +fn decision_label(decision: &DeliveryDecision) -> &'static str { + match decision { + DeliveryDecision::Deliver { .. } => "deliver", + DeliveryDecision::Duplicate { .. } => "duplicate", + DeliveryDecision::Stale { .. } => "stale", + DeliveryDecision::Gap { .. } => "gap", + DeliveryDecision::IdentityReject => "identity_reject", + } +} + +/// One observed `deliver` frame, reduced to non-sensitive fields. +#[derive(Debug, Clone)] +struct RecentDeliver { + at_ms: u64, + agent: String, + agent_id: String, + delivery_id: String, + msg_id: String, + seq: u64, + payload_type: String, + decision: &'static str, + disposition: Option<&'static str>, +} + +impl RecentDeliver { + fn to_json(&self) -> Value { + json!({ + "at_ms": self.at_ms, + "agent": self.agent, + "agent_id": self.agent_id, + "delivery_id": self.delivery_id, + "msg_id": self.msg_id, + "seq": self.seq, + "payload_type": self.payload_type, + "decision": self.decision, + "disposition": self.disposition, + }) + } +} + +/// The last frame the broker could not deserialize. The raw frame is never +/// retained — only its length, its `type` discriminator when one is readable, +/// and a bounded serde error. +#[derive(Debug, Clone)] +struct ParseFailure { + at_ms: u64, + error: String, + frame_type: Option, + frame_len: usize, +} + +/// A published view of the runtime's delivery-book cursors. The book itself +/// lives inside the single-threaded runtime; the runtime republishes this +/// snapshot as it handles frames so the endpoint can read cursors without +/// reaching into the event loop. +#[derive(Debug, Clone, Default)] +pub(crate) struct CursorSnapshot { + pub(crate) published_at_ms: u64, + pub(crate) agents: Vec, +} + +#[derive(Debug, Clone)] +pub(crate) struct AgentCursorView { + pub(crate) agent_id: String, + pub(crate) agent_name: String, + pub(crate) acked_up_to_seq: u64, + pub(crate) received_up_to_seq: u64, + pub(crate) has_sequenced_position: bool, +} + +/// Per-agent delivery tally. +/// +/// The global counters answer "is this broker receiving anything". They cannot +/// answer "is *this* agent deaf", which is the question an operator actually +/// has — see relay#1593, where sends kept reporting `recipientMatched: true` +/// and `pending_messages` stayed 0 on the affected agents while unaffected +/// agents on the same broker delivered normally. Global counters look healthy +/// throughout that failure, and the recent-frame ring is FIFO, so on a busy +/// broker the relevant frames are evicted long before anyone looks. +/// +/// These rows persist per agent, so the diagnosis is a single read: +/// `delivers_seen` not advancing for the agent means the frame never reached +/// this broker (look upstream); advancing while `injected` does not means the +/// delivery book discarded it, and the decision counts say which way. +/// `last_injected_at_ms` is the per-route last-confirmed-delivery asked for in +/// relay#1593 — it separates a deaf agent from a merely quiet one. +#[derive(Debug, Default, Clone)] +struct AgentStats { + agent_id: String, + delivers_seen: u64, + decision_deliver: u64, + decision_duplicate: u64, + decision_stale: u64, + decision_gap: u64, + decision_identity_reject: u64, + injected: u64, + surfaced_and_acked: u64, + held_for_manual_flush: u64, + surface_failed: u64, + acked_without_surfacing: u64, + rejected_identity: u64, + rejected_sequence_gap: u64, + last_deliver_at_ms: u64, + last_injected_at_ms: u64, + /// Strictly increasing rank of the last time this row was touched. See + /// [`agent_row`] — eviction orders on this, not on the millisecond clock. + last_touch_order: u64, +} + +impl AgentStats { + fn to_json(&self, name: &str) -> Value { + json!({ + "agent": name, + "agent_id": self.agent_id, + "delivers_seen": self.delivers_seen, + "decisions": { + "deliver": self.decision_deliver, + "duplicate": self.decision_duplicate, + "stale": self.decision_stale, + "gap": self.decision_gap, + "identity_reject": self.decision_identity_reject, + }, + "dispositions": { + "injected": self.injected, + "surfaced_and_acked": self.surfaced_and_acked, + "held_for_manual_flush": self.held_for_manual_flush, + "surface_failed": self.surface_failed, + "acked_without_surfacing": self.acked_without_surfacing, + "rejected_identity": self.rejected_identity, + "rejected_sequence_gap": self.rejected_sequence_gap, + }, + "last_deliver_at_ms": non_zero(self.last_deliver_at_ms), + "last_injected_at_ms": non_zero(self.last_injected_at_ms), + }) + } +} + +#[derive(Debug, Default)] +struct Counters { + text_frames: AtomicU64, + parse_failures: AtomicU64, + deliver: AtomicU64, + action_invoke: AtomicU64, + ping: AtomicU64, + reply: AtomicU64, + error: AtomicU64, + decision_deliver: AtomicU64, + decision_duplicate: AtomicU64, + decision_stale: AtomicU64, + decision_gap: AtomicU64, + decision_identity_reject: AtomicU64, + injected: AtomicU64, + surfaced_and_acked: AtomicU64, + held_for_manual_flush: AtomicU64, + surface_failed: AtomicU64, + acked_without_surfacing: AtomicU64, + rejected_identity: AtomicU64, + rejected_sequence_gap: AtomicU64, + connects: AtomicU64, + disconnects: AtomicU64, + /// Whether a node-control session is currently established. + /// + /// Kept separately from the two tallies rather than derived from them: + /// reading `connects` and `disconnects` as two Relaxed loads can observe + /// a stale `connects` beside a fresh `disconnects` and briefly report a + /// live session as dead. The tallies stay because reconnect churn is + /// itself diagnostic, but the flag is what `connected` reports. + session_live: std::sync::atomic::AtomicBool, + last_deliver_at_ms: AtomicU64, + last_frame_at_ms: AtomicU64, + /// Ticket dispenser for [`AgentStats::last_touch_order`]. + agent_touch_order: AtomicU64, + ack_enqueued: AtomicU64, + ack_enqueue_failed: AtomicU64, + ack_sent: AtomicU64, + ack_send_failed: AtomicU64, + last_ack_sent_at_ms: AtomicU64, +} + +#[derive(Debug, Default)] +struct Retained { + recent: std::collections::VecDeque, + agents: BTreeMap, + last_parse_failure: Option, + unparsed_frame_types: BTreeMap, + cursors: CursorSnapshot, +} + +/// Shared, `RUST_LOG`-independent introspection for the node-control inbound +/// path. Cloned as an `Arc` into the node-control client task, the runtime, and +/// the HTTP API. +#[derive(Debug, Default)] +pub(crate) struct NodeDeliveryProbe { + counters: Counters, + retained: Mutex, +} + +impl NodeDeliveryProbe { + pub(crate) fn new() -> Self { + Self::default() + } + + /// Mint the next strictly-increasing agent-row touch rank. + fn next_agent_touch(&self) -> u64 { + self.counters + .agent_touch_order + .fetch_add(1, Ordering::Relaxed) + } + + pub(crate) fn record_connected(&self) { + self.counters.connects.fetch_add(1, Ordering::Relaxed); + self.counters.session_live.store(true, Ordering::Relaxed); + } + + pub(crate) fn record_disconnected(&self) { + self.counters.disconnects.fetch_add(1, Ordering::Relaxed); + self.counters.session_live.store(false, Ordering::Relaxed); + } + + /// Called for every inbound WS text frame, before any deserialization. + /// This is the counter that answers "did anything arrive at all". + pub(crate) fn record_text_frame(&self) { + self.counters.text_frames.fetch_add(1, Ordering::Relaxed); + self.counters + .last_frame_at_ms + .store(now_ms(), Ordering::Relaxed); + } + + /// Called when a text frame failed to deserialize into `ServerToNode`. + /// `raw` is inspected only to recover the `type` discriminator; it is + /// never retained. + pub(crate) fn record_parse_failure(&self, error: &str, raw: &str) { + self.counters.parse_failures.fetch_add(1, Ordering::Relaxed); + let frame_type = serde_json::from_str::(raw) + .ok() + .and_then(|value| value.get("type").and_then(Value::as_str).map(bounded)); + let mut error = error.to_string(); + truncate_on_char_boundary(&mut error, ERROR_EXCERPT_LIMIT); + let Ok(mut retained) = self.retained.lock() else { + return; + }; + if let Some(found) = frame_type.clone() { + // Bounded: only count a new discriminator while there is room, so a + // misbehaving peer cannot grow this map without limit. Existing + // keys keep counting either way. + let known = retained.unparsed_frame_types.contains_key(&found); + if known || retained.unparsed_frame_types.len() < UNPARSED_TYPE_CAPACITY { + *retained.unparsed_frame_types.entry(found).or_insert(0) += 1; + } + } + retained.last_parse_failure = Some(ParseFailure { + at_ms: now_ms(), + error, + frame_type, + frame_len: raw.len(), + }); + } + + /// Called for every successfully-deserialized inbound frame. + pub(crate) fn record_frame(&self, frame: &RelaycastToBroker) { + let counter = match frame { + RelaycastToBroker::Deliver(_) => &self.counters.deliver, + RelaycastToBroker::ActionInvoke(_) => &self.counters.action_invoke, + RelaycastToBroker::Ping(_) => &self.counters.ping, + RelaycastToBroker::Reply(_) => &self.counters.reply, + RelaycastToBroker::Error(_) => &self.counters.error, + }; + counter.fetch_add(1, Ordering::Relaxed); + if matches!(frame, RelaycastToBroker::Deliver(_)) { + self.counters + .last_deliver_at_ms + .store(now_ms(), Ordering::Relaxed); + } + } + + /// Called by the runtime with the delivery book's verdict on a frame, + /// before that verdict has been acted on. + pub(crate) fn record_decision(&self, deliver: &Deliver, decision: &DeliveryDecision) { + let counter = match decision { + DeliveryDecision::Deliver { .. } => &self.counters.decision_deliver, + DeliveryDecision::Duplicate { .. } => &self.counters.decision_duplicate, + DeliveryDecision::Stale { .. } => &self.counters.decision_stale, + DeliveryDecision::Gap { .. } => &self.counters.decision_gap, + DeliveryDecision::IdentityReject => &self.counters.decision_identity_reject, + }; + counter.fetch_add(1, Ordering::Relaxed); + + let payload_type = bounded( + deliver + .payload + .get("type") + .and_then(Value::as_str) + .unwrap_or(""), + ); + let now = now_ms(); + let touch = self.next_agent_touch(); + let entry = RecentDeliver { + at_ms: now, + agent: bounded(&deliver.agent), + agent_id: bounded(&deliver.agent_id), + delivery_id: bounded(&deliver.delivery_id), + msg_id: bounded(&deliver.msg_id), + seq: deliver.seq, + payload_type, + decision: decision_label(decision), + disposition: None, + }; + let Ok(mut retained) = self.retained.lock() else { + return; + }; + if retained.recent.len() == RECENT_CAPACITY { + retained.recent.pop_front(); + } + retained.recent.push_back(entry); + + // Per-agent row: survives the ring's FIFO eviction, which is what makes + // a single deaf agent diagnosable on a busy broker. See `AgentStats`. + if let Some(stats) = agent_row(&mut retained.agents, &bounded(&deliver.agent), touch) { + stats.agent_id = bounded(&deliver.agent_id); + stats.delivers_seen += 1; + stats.last_deliver_at_ms = now; + match decision { + DeliveryDecision::Deliver { .. } => stats.decision_deliver += 1, + DeliveryDecision::Duplicate { .. } => stats.decision_duplicate += 1, + DeliveryDecision::Stale { .. } => stats.decision_stale += 1, + DeliveryDecision::Gap { .. } => stats.decision_gap += 1, + DeliveryDecision::IdentityReject => stats.decision_identity_reject += 1, + } + } + } + + /// Called once `handle_fleet_deliver` knows where the frame ended up. The + /// disposition is stamped onto the matching recent entry so a reader sees + /// decision and outcome together rather than having to infer the join. + pub(crate) fn record_disposition(&self, deliver: &Deliver, disposition: DeliverDisposition) { + let counter = match disposition { + DeliverDisposition::Injected => &self.counters.injected, + DeliverDisposition::SurfacedAndAcked => &self.counters.surfaced_and_acked, + DeliverDisposition::HeldForManualFlush => &self.counters.held_for_manual_flush, + DeliverDisposition::SurfaceFailed => &self.counters.surface_failed, + DeliverDisposition::AckedWithoutSurfacing => &self.counters.acked_without_surfacing, + DeliverDisposition::RejectedIdentity => &self.counters.rejected_identity, + DeliverDisposition::RejectedSequenceGap => &self.counters.rejected_sequence_gap, + }; + counter.fetch_add(1, Ordering::Relaxed); + let touch = self.next_agent_touch(); + let delivery_id = bounded(&deliver.delivery_id); + let Ok(mut retained) = self.retained.lock() else { + return; + }; + if let Some(entry) = retained + .recent + .iter_mut() + .rev() + .find(|entry| entry.delivery_id == delivery_id) + { + entry.disposition = Some(disposition.as_str()); + } + if let Some(stats) = agent_row(&mut retained.agents, &bounded(&deliver.agent), touch) { + match disposition { + DeliverDisposition::Injected => { + stats.injected += 1; + // The per-route "last confirmed delivery" relay#1593 asked + // for: it separates a deaf agent from a merely quiet one. + stats.last_injected_at_ms = now_ms(); + } + DeliverDisposition::SurfacedAndAcked => stats.surfaced_and_acked += 1, + DeliverDisposition::HeldForManualFlush => stats.held_for_manual_flush += 1, + DeliverDisposition::SurfaceFailed => stats.surface_failed += 1, + DeliverDisposition::AckedWithoutSurfacing => stats.acked_without_surfacing += 1, + DeliverDisposition::RejectedIdentity => stats.rejected_identity += 1, + DeliverDisposition::RejectedSequenceGap => stats.rejected_sequence_gap += 1, + } + } + } + + /// The runtime handed a `delivery_ack` to the node-control task. + /// + /// A disposition of `surfaced_and_acked` or `acked_without_surfacing` only + /// says the *broker* decided to acknowledge. It is recorded before the ack + /// has gone anywhere, and it cannot be recorded later: the runtime event + /// loop hands the ack to the socket task over a channel and must not block + /// on the wire, so the two events genuinely happen in different places. The + /// four tallies below close that gap without coupling them — an operator + /// reads `dispositions.surfaced_and_acked` against `acks.sent` and sees + /// directly whether the engine was told. `enqueued` > `sent` means acks are + /// stuck between the runtime and the socket; `enqueue_failed` means the + /// control task is gone; `send_failed` means the socket rejected the write. + pub(crate) fn record_ack_enqueued(&self) { + self.counters.ack_enqueued.fetch_add(1, Ordering::Relaxed); + } + + /// The runtime could not hand a `delivery_ack` to the node-control task at + /// all — the command channel is closed or full, so the engine will never + /// see this ack and will redeliver. + pub(crate) fn record_ack_enqueue_failed(&self) { + self.counters + .ack_enqueue_failed + .fetch_add(1, Ordering::Relaxed); + } + + /// The node-control task wrote a `delivery_ack` to the socket. + pub(crate) fn record_ack_sent(&self) { + self.counters.ack_sent.fetch_add(1, Ordering::Relaxed); + self.counters + .last_ack_sent_at_ms + .store(now_ms(), Ordering::Relaxed); + } + + /// The node-control task failed to write a `delivery_ack` to the socket. + pub(crate) fn record_ack_send_failed(&self) { + self.counters + .ack_send_failed + .fetch_add(1, Ordering::Relaxed); + } + + /// Republish the runtime's delivery-book cursors. Called from the runtime, + /// which owns the book. + pub(crate) fn publish_cursors(&self, agents: Vec) { + let Ok(mut retained) = self.retained.lock() else { + return; + }; + retained.cursors = CursorSnapshot { + published_at_ms: now_ms(), + agents, + }; + } + + /// Render the probe for `GET /api/node-delivery`. + /// + /// `connected` is derived from the probe's own connect/disconnect tallies + /// rather than read from the runtime, so the endpoint needs nothing from + /// the event loop to answer. + pub(crate) fn snapshot_with_token(&self, token_present: bool) -> Value { + let connected = self.counters.session_live.load(Ordering::Relaxed); + self.snapshot(connected, token_present) + } + + fn snapshot(&self, connected: bool, token_present: bool) -> Value { + let c = &self.counters; + let load = |a: &AtomicU64| a.load(Ordering::Relaxed); + let (recent, parse_failure, unparsed, cursors, agents) = match self.retained.lock() { + Ok(retained) => ( + retained + .recent + .iter() + .map(RecentDeliver::to_json) + .collect::>(), + retained.last_parse_failure.clone(), + retained.unparsed_frame_types.clone(), + retained.cursors.clone(), + retained + .agents + .iter() + .map(|(name, stats)| stats.to_json(name)) + .collect::>(), + ), + // A poisoned lock must not take the diagnostic offline; the + // counters are still meaningful on their own. + Err(_) => ( + Vec::new(), + None, + BTreeMap::new(), + CursorSnapshot::default(), + Vec::new(), + ), + }; + + json!({ + "connected": connected, + "token_present": token_present, + "now_ms": now_ms(), + "socket": { + "connects": load(&c.connects), + "disconnects": load(&c.disconnects), + "text_frames": load(&c.text_frames), + "parse_failures": load(&c.parse_failures), + "last_frame_at_ms": non_zero(load(&c.last_frame_at_ms)), + }, + "frames": { + "deliver": load(&c.deliver), + "action_invoke": load(&c.action_invoke), + "ping": load(&c.ping), + "reply": load(&c.reply), + "error": load(&c.error), + "last_deliver_at_ms": non_zero(load(&c.last_deliver_at_ms)), + }, + "decisions": { + "deliver": load(&c.decision_deliver), + "duplicate": load(&c.decision_duplicate), + "stale": load(&c.decision_stale), + "gap": load(&c.decision_gap), + "identity_reject": load(&c.decision_identity_reject), + }, + "dispositions": { + "injected": load(&c.injected), + "surfaced_and_acked": load(&c.surfaced_and_acked), + "held_for_manual_flush": load(&c.held_for_manual_flush), + "surface_failed": load(&c.surface_failed), + "acked_without_surfacing": load(&c.acked_without_surfacing), + "rejected_identity": load(&c.rejected_identity), + "rejected_sequence_gap": load(&c.rejected_sequence_gap), + }, + "acks": { + "enqueued": load(&c.ack_enqueued), + "enqueue_failed": load(&c.ack_enqueue_failed), + "sent": load(&c.ack_sent), + "send_failed": load(&c.ack_send_failed), + "last_sent_at_ms": non_zero(load(&c.last_ack_sent_at_ms)), + }, + "agents": agents, + "recent_delivers": recent, + "unparsed_frame_types": unparsed, + "last_parse_failure": parse_failure.map(|failure| json!({ + "at_ms": failure.at_ms, + "error": failure.error, + "frame_type": failure.frame_type, + "frame_len": failure.frame_len, + })), + "cursors_published_at_ms": non_zero(cursors.published_at_ms), + "cursors": cursors.agents.iter().map(|agent| json!({ + "agent_id": agent.agent_id, + "agent_name": agent.agent_name, + "acked_up_to_seq": agent.acked_up_to_seq, + "received_up_to_seq": agent.received_up_to_seq, + "has_sequenced_position": agent.has_sequenced_position, + })).collect::>(), + }) + } +} + +/// Fetch (or create) an agent's row, evicting the least recently touched agent +/// when full. +/// +/// Agent names arrive from the engine, so a first-wins bound would let a +/// buggy peer occupy every slot with names that never deliver again and +/// starve the agents an operator is actually watching — which defeats the +/// point of these rows. Evicting the least recently touched row keeps the most +/// recently active agents, which are the ones a diagnosis is about. +/// +/// `touch` rather than `last_deliver_at_ms` decides that order. The wall clock +/// has millisecond resolution and a busy broker takes many frames per +/// millisecond, so timestamps tie routinely; the old tiebreak was the agent +/// *name*, which meant a newly active `"a"` was evicted ahead of a long-idle +/// `"z"` — an operator would find the row for the agent they are watching gone +/// because of its name. `touch` is a strictly increasing ticket, so the order +/// is exact and no tiebreak is needed. +fn agent_row<'a>( + agents: &'a mut BTreeMap, + agent: &str, + touch: u64, +) -> Option<&'a mut AgentStats> { + if !agents.contains_key(agent) && agents.len() >= AGENT_STATS_CAPACITY { + let stalest = agents + .iter() + .min_by_key(|(_, stats)| stats.last_touch_order) + .map(|(name, _)| name.clone())?; + agents.remove(&stalest); + } + let stats = agents.entry(agent.to_string()).or_default(); + stats.last_touch_order = touch; + Some(stats) +} + +/// Shorten `value` to at most `limit` BYTES without splitting a character. +/// +/// `String::truncate` panics when the index is not a UTF-8 boundary. The string +/// this bounds is a serde error, and serde quotes the offending input into its +/// message — so a frame carrying a long non-ASCII discriminator can put a +/// multi-byte character across the limit. That panic would unwind the sole +/// spawned node-control client task and take realtime delivery down with it: +/// a malformed frame would make the broker deaf, through the very code added +/// to diagnose deafness. Walking back to a boundary keeps the byte bound +/// (unlike taking N `chars`, which can still admit 4x the bytes). +fn truncate_on_char_boundary(value: &mut String, limit: usize) { + if value.len() <= limit { + return; + } + let mut end = limit; + while end > 0 && !value.is_char_boundary(end) { + end -= 1; + } + value.truncate(end); +} + +/// Copy a peer-supplied string into retained state under [`PEER_STRING_LIMIT`]. +/// +/// Every retained peer string goes through here, and every *comparison* against +/// a retained peer string must too — `record_disposition` matches on +/// `delivery_id` and both `record_decision` and `record_disposition` key the +/// agent map by name, so bounding one side only would silently stop the +/// disposition from landing on its frame. Truncation is deterministic, so +/// bounding both sides preserves the match. +fn bounded(value: &str) -> String { + let mut owned = value.to_string(); + truncate_on_char_boundary(&mut owned, PEER_STRING_LIMIT); + owned +} + +/// Render a never-set timestamp as `null` rather than `0`, so a reader cannot +/// mistake "no frame has ever arrived" for "a frame arrived at the epoch". +fn non_zero(value: u64) -> Option { + (value != 0).then_some(value) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::fleet_wire::{DeliveryMode, FleetWireVersion}; + use serde_json::json; + + fn deliver(agent: &str, agent_id: &str, delivery_id: &str, seq: u64) -> Deliver { + Deliver { + v: FleetWireVersion, + agent: agent.to_string(), + agent_id: agent_id.to_string(), + delivery_id: delivery_id.to_string(), + msg_id: format!("msg_{delivery_id}"), + seq, + mode: DeliveryMode::Wait, + payload: json!({ "type": "message.created", "body": "unused" }), + } + } + + /// The property the whole module exists for: a `deliver` frame the broker + /// cannot deserialize must still be counted as having ARRIVED. Counting + /// only parsed frames would report "nothing reached this broker" for a + /// broker that is receiving deliveries and discarding them — the exact + /// wrong answer to the question the endpoint is asked. + #[test] + fn unparseable_deliver_still_counts_as_arrived() { + let probe = NodeDeliveryProbe::new(); + // A frame the wire enum does not know. `ServerToNode` is + // `#[serde(tag = "type")]`, so this fails `from_str` as a whole. + let raw = r#"{"type":"deliver.v2","agent":"a","seq":9}"#; + probe.record_text_frame(); + probe.record_parse_failure("unknown variant `deliver.v2`", raw); + + let snapshot = probe.snapshot_with_token(true); + assert_eq!(snapshot["socket"]["text_frames"], 1); + assert_eq!(snapshot["socket"]["parse_failures"], 1); + // Parsed-frame counters stay zero: the frame arrived and was lost. + assert_eq!(snapshot["frames"]["deliver"], 0); + assert_eq!(snapshot["unparsed_frame_types"]["deliver.v2"], 1); + assert_eq!( + snapshot["last_parse_failure"]["frame_type"], + json!("deliver.v2") + ); + assert_eq!(snapshot["last_parse_failure"]["frame_len"], raw.len()); + } + + /// A parse failure must never retain the frame itself — a `deliver` + /// payload carries message bodies, and this endpoint is meant to be safe + /// to paste into an issue. + #[test] + fn parse_failure_does_not_retain_the_frame_body() { + let probe = NodeDeliveryProbe::new(); + let raw = r#"{"type":"mystery","payload":{"body":"hunter2-secret-body"}}"#; + probe.record_parse_failure("unknown variant `mystery`", raw); + + let rendered = probe.snapshot_with_token(true).to_string(); + assert!( + !rendered.contains("hunter2-secret-body"), + "probe leaked a frame body: {rendered}" + ); + } + + /// Likewise for the recent-frame ring: identifiers and the payload's own + /// `type` discriminator, never the message text. + #[test] + fn recent_delivers_record_ids_but_not_message_bodies() { + let probe = NodeDeliveryProbe::new(); + let mut frame = deliver("worker", "ag_1", "del_1", 1); + frame.payload = json!({ "type": "dm.received", "body": "hunter2-secret-body" }); + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); + + let snapshot = probe.snapshot_with_token(true); + let entry = &snapshot["recent_delivers"][0]; + assert_eq!(entry["agent"], "worker"); + assert_eq!(entry["delivery_id"], "del_1"); + assert_eq!(entry["seq"], 1); + assert_eq!(entry["payload_type"], "dm.received"); + assert!(!snapshot.to_string().contains("hunter2-secret-body")); + } + + /// "Where did it stop" is the second half of the question, so the decision + /// and the disposition must be readable together on one entry rather than + /// left for the reader to join by hand. + #[test] + fn disposition_lands_on_the_matching_recent_entry() { + let probe = NodeDeliveryProbe::new(); + let first = deliver("worker", "ag_1", "del_1", 1); + let second = deliver("worker", "ag_1", "del_2", 2); + probe.record_decision(&first, &DeliveryDecision::Deliver { up_to_seq: 1 }); + probe.record_decision(&second, &DeliveryDecision::IdentityReject); + probe.record_disposition(&first, DeliverDisposition::Injected); + probe.record_disposition(&second, DeliverDisposition::RejectedIdentity); + + let snapshot = probe.snapshot_with_token(true); + let recent = snapshot["recent_delivers"].as_array().expect("array"); + assert_eq!(recent.len(), 2); + assert_eq!(recent[0]["delivery_id"], "del_1"); + assert_eq!(recent[0]["decision"], "deliver"); + assert_eq!(recent[0]["disposition"], "injected"); + assert_eq!(recent[1]["delivery_id"], "del_2"); + assert_eq!(recent[1]["decision"], "identity_reject"); + assert_eq!(recent[1]["disposition"], "rejected_identity"); + assert_eq!(snapshot["decisions"]["deliver"], 1); + assert_eq!(snapshot["decisions"]["identity_reject"], 1); + assert_eq!(snapshot["dispositions"]["injected"], 1); + assert_eq!(snapshot["dispositions"]["rejected_identity"], 1); + } + + /// A long-running broker must not accumulate frame history without bound. + #[test] + fn recent_delivers_are_capped() { + let probe = NodeDeliveryProbe::new(); + for seq in 0..(RECENT_CAPACITY as u64 + 10) { + let frame = deliver("worker", "ag_1", &format!("del_{seq}"), seq); + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: seq }); + } + let snapshot = probe.snapshot_with_token(true); + let recent = snapshot["recent_delivers"].as_array().expect("array"); + assert_eq!(recent.len(), RECENT_CAPACITY); + // Oldest evicted, newest retained. + assert_eq!(recent[0]["delivery_id"], "del_10"); + assert_eq!( + recent[RECENT_CAPACITY - 1]["delivery_id"], + format!("del_{}", RECENT_CAPACITY + 9) + ); + // The counter still reflects every frame, not just the retained ones. + assert_eq!( + snapshot["decisions"]["deliver"], + RECENT_CAPACITY as u64 + 10 + ); + } + + /// A peer emitting endless distinct `type` values must not grow this map + /// without limit; counts for already-known types keep advancing. + #[test] + fn unparsed_frame_type_map_is_bounded() { + let probe = NodeDeliveryProbe::new(); + for index in 0..(UNPARSED_TYPE_CAPACITY + 25) { + probe.record_parse_failure("boom", &format!(r#"{{"type":"kind{index}"}}"#)); + } + // A type recorded while there was room keeps counting after the cap. + probe.record_parse_failure("boom", r#"{"type":"kind0"}"#); + + let snapshot = probe.snapshot_with_token(true); + let map = snapshot["unparsed_frame_types"] + .as_object() + .expect("object"); + assert_eq!(map.len(), UNPARSED_TYPE_CAPACITY); + assert_eq!(map["kind0"], 2); + // Every failure is still counted even when its type is not retained. + assert_eq!( + snapshot["socket"]["parse_failures"], + (UNPARSED_TYPE_CAPACITY + 26) as u64 + ); + } + + /// A never-set timestamp renders as null, so "no frame has ever arrived" + /// cannot be misread as "a frame arrived at the unix epoch". + /// relay#1680 review (P1). `record_parse_failure` runs inside the sole + /// spawned node-control client task. serde quotes the offending input into + /// its error text, so a frame with a long non-ASCII discriminator puts a + /// multi-byte character across the 300-byte limit; `String::truncate` then + /// panics, unwinds that task, and takes realtime delivery with it. A + /// malformed frame would make the broker deaf through the very code added + /// to diagnose deafness. + #[test] + fn oversized_non_ascii_parse_error_does_not_panic() { + let probe = NodeDeliveryProbe::new(); + // One ASCII byte then 2-byte chars, so every subsequent boundary is at + // an odd offset and the even 300-byte limit lands mid-character. + let long_error = format!("a{}", "é".repeat(400)); + assert!(long_error.len() > ERROR_EXCERPT_LIMIT); + assert!(!long_error.is_char_boundary(ERROR_EXCERPT_LIMIT)); + + probe.record_parse_failure(&long_error, r#"{"type":"deliver"}"#); + + let snapshot = probe.snapshot_with_token(true); + let recorded = snapshot["last_parse_failure"]["error"] + .as_str() + .expect("the failure must still be recorded"); + // Truncated on a boundary, and still bounded in BYTES — taking N chars + // instead would admit up to 4x the limit. + assert!(recorded.len() <= ERROR_EXCERPT_LIMIT); + assert!(long_error.starts_with(recorded)); + assert_eq!(snapshot["socket"]["parse_failures"], 1); + } + + #[test] + fn truncation_keeps_whole_characters_and_the_byte_bound() { + let mut value = format!("a{}", "é".repeat(400)); + assert!(!value.is_char_boundary(ERROR_EXCERPT_LIMIT)); + truncate_on_char_boundary(&mut value, ERROR_EXCERPT_LIMIT); + assert!(value.len() <= ERROR_EXCERPT_LIMIT); + // `String::truncate` would have panicked on that index; this stops one + // byte short of it, on the boundary. + assert_eq!(value.len(), ERROR_EXCERPT_LIMIT - 1); + assert!(value.starts_with('a')); + assert!(value.chars().skip(1).all(|c| c == 'é')); + + let mut short = "ascii".to_string(); + truncate_on_char_boundary(&mut short, ERROR_EXCERPT_LIMIT); + assert_eq!(short, "ascii"); + } + + /// relay#1593: sends kept reporting `recipientMatched: true` while + /// `pending_messages` stayed 0 on the affected agents and unaffected + /// agents on the same broker delivered normally. Global counters look + /// healthy right through that, so the per-agent rows are what make a + /// single deaf agent diagnosable. + #[test] + fn per_agent_rows_localize_a_single_deaf_agent() { + let probe = NodeDeliveryProbe::new(); + + // A healthy agent: frame arrives and is injected. + let healthy = deliver("healthy-agent", "ag_ok", "del_ok", 1); + probe.record_decision(&healthy, &DeliveryDecision::Deliver { up_to_seq: 1 }); + probe.record_disposition(&healthy, DeliverDisposition::Injected); + + // A deaf agent: the frame reaches the broker but the delivery book + // rejects it on identity, so it never enters the pending queue — + // which is exactly why `pending_messages` reads 0 in relay#1593. + let deaf = deliver("deaf-agent", "ag_stale", "del_stale", 7); + probe.record_decision(&deaf, &DeliveryDecision::IdentityReject); + probe.record_disposition(&deaf, DeliverDisposition::RejectedIdentity); + + let snapshot = probe.snapshot_with_token(true); + let rows = snapshot["agents"].as_array().expect("agents array"); + let row = |name: &str| { + rows.iter() + .find(|row| row["agent"] == name) + .unwrap_or_else(|| panic!("missing row for {name}")) + .clone() + }; + + let healthy_row = row("healthy-agent"); + assert_eq!(healthy_row["delivers_seen"], 1); + assert_eq!(healthy_row["dispositions"]["injected"], 1); + assert!(healthy_row["last_injected_at_ms"].is_u64()); + + let deaf_row = row("deaf-agent"); + // The frame DID arrive — so this is not an upstream problem... + assert_eq!(deaf_row["delivers_seen"], 1); + assert_eq!(deaf_row["decisions"]["identity_reject"], 1); + // ...but it was never injected, and the per-route last-confirmed + // delivery relay#1593 asked for is null, separating deaf from quiet. + assert_eq!(deaf_row["dispositions"]["injected"], 0); + assert_eq!(deaf_row["last_injected_at_ms"], Value::Null); + assert!(deaf_row["last_deliver_at_ms"].is_u64()); + } + + /// An agent that is merely quiet has no row at all, which is a different + /// answer from "frames arrived and went nowhere" and must not be confused + /// with it. + /// `Gap` and `IdentityReject` both reject without acking, but they are + /// different diagnoses — a gap means the book could not place a frame the + /// agent never saw, an identity reject means the frame was addressed to a + /// retired incarnation. Collapsing them would point an operator at the + /// wrong half of the system. + #[test] + fn a_sequence_gap_is_not_reported_as_an_identity_reject() { + let probe = NodeDeliveryProbe::new(); + let gapped = deliver("agent-a", "ag_a", "del_gap", 9); + probe.record_decision(&gapped, &DeliveryDecision::Gap { up_to_seq: 4 }); + probe.record_disposition(&gapped, DeliverDisposition::RejectedSequenceGap); + + let snapshot = probe.snapshot_with_token(true); + assert_eq!(snapshot["dispositions"]["rejected_sequence_gap"], 1); + assert_eq!(snapshot["dispositions"]["rejected_identity"], 0); + assert_eq!(snapshot["decisions"]["gap"], 1); + assert_eq!(snapshot["recent_delivers"][0]["decision"], "gap"); + assert_eq!( + snapshot["recent_delivers"][0]["disposition"], + "rejected_sequence_gap" + ); + let row = &snapshot["agents"][0]; + assert_eq!(row["dispositions"]["rejected_sequence_gap"], 1); + assert_eq!(row["dispositions"]["rejected_identity"], 0); + // Arrived, never delivered: the pair that localizes the failure. + assert_eq!(row["delivers_seen"], 1); + assert_eq!(row["last_injected_at_ms"], Value::Null); + } + + #[test] + fn an_agent_with_no_frames_has_no_row() { + let probe = NodeDeliveryProbe::new(); + let frame = deliver("busy-agent", "ag_1", "del_1", 1); + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); + + let snapshot = probe.snapshot_with_token(true); + let rows = snapshot["agents"].as_array().expect("agents array"); + assert_eq!(rows.len(), 1); + assert_eq!(rows[0]["agent"], "busy-agent"); + } + + /// Bounded, and bounded the right way round: the rows that survive are the + /// most recently delivered-to. A first-wins bound would let a peer that + /// invents names starve the agents an operator is actually watching. + // relay#1680 review (coderabbitai, node_delivery_probe.rs:592) MUST-FIRE: + // `last_deliver_at_ms` is a millisecond clock and a busy broker takes many + // frames per millisecond, so rows tie routinely. The old tiebreak was the + // agent NAME, which evicted a just-active `"aaa-fresh"` ahead of a long-idle + // `"zzz-stale"` — the operator's row disappears because of its name. + // + // Driven through `agent_row` directly and with every `last_deliver_at_ms` + // pinned to one value, so the wall clock cannot accidentally break the tie + // and let the unfixed code pass. Against `(last_deliver_at_ms, name)` this + // fails on the `aaa-fresh` assertion. + #[test] + fn eviction_orders_on_activity_not_on_the_agent_name() { + let mut agents: BTreeMap = BTreeMap::new(); + let same_millisecond = 1_700_000_000_000; + for index in 0..AGENT_STATS_CAPACITY { + let name = match index { + 0 => "zzz-stale".to_string(), + n if n == AGENT_STATS_CAPACITY - 1 => "aaa-fresh".to_string(), + n => format!("filler-{n:04}"), + }; + let row = agent_row(&mut agents, &name, index as u64).expect("row"); + row.last_deliver_at_ms = same_millisecond; + } + assert_eq!(agents.len(), AGENT_STATS_CAPACITY); + + // Full: admitting one more name must evict exactly one row. + agent_row(&mut agents, "newcomer", AGENT_STATS_CAPACITY as u64).expect("row"); + assert_eq!(agents.len(), AGENT_STATS_CAPACITY); + assert!( + !agents.contains_key("zzz-stale"), + "the least recently touched row must be the one evicted" + ); + assert!( + agents.contains_key("aaa-fresh"), + "a freshly active agent must not be evicted ahead of an idle one \ + just because its name sorts first" + ); + } + + // relay#1680 review (coderabbitai, node_delivery_probe.rs:331) MUST-FIRE: + // the slot counts bound how MANY peer strings are retained; without a + // per-field bound one oversized value multiplies across every slot. Asserts + // the bound at each retention site, and — because `record_disposition` + // joins on `delivery_id` and both writers key the agent map by name — that + // bounding both sides kept the disposition landing on its frame. + #[test] + fn peer_supplied_strings_are_bounded_before_retention() { + let probe = NodeDeliveryProbe::new(); + let oversized = "x".repeat(4_096); + let mut frame = deliver(&oversized, &oversized, &oversized, 1); + frame.payload = json!({ "type": oversized }); + + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); + probe.record_disposition(&frame, DeliverDisposition::Injected); + probe.record_parse_failure("boom", &json!({ "type": oversized }).to_string()); + + let snapshot = probe.snapshot_with_token(true); + let row = &snapshot["recent_delivers"][0]; + for field in ["agent", "agent_id", "delivery_id", "msg_id", "payload_type"] { + let value = row[field].as_str().expect(field); + assert!( + value.len() <= PEER_STRING_LIMIT, + "recent_delivers.{field} retained {} bytes of peer text", + value.len() + ); + } + assert_eq!( + row["disposition"], "injected", + "bounding the retained delivery_id must not break the join that \ + stamps the disposition onto its frame" + ); + + let agent = snapshot["agents"][0]["agent"].as_str().expect("agent row"); + assert!( + agent.len() <= PEER_STRING_LIMIT, + "the agent map key retained {} bytes of peer text", + agent.len() + ); + assert_eq!( + snapshot["agents"][0]["dispositions"]["injected"], 1, + "bounding the agent name on both writers must keep them on one row" + ); + + let frame_type = snapshot["last_parse_failure"]["frame_type"] + .as_str() + .expect("frame_type"); + assert!( + frame_type.len() <= PEER_STRING_LIMIT, + "the parse-failure discriminator retained {} bytes", + frame_type.len() + ); + for key in snapshot["unparsed_frame_types"] + .as_object() + .expect("unparsed map") + .keys() + { + assert!( + key.len() <= PEER_STRING_LIMIT, + "an unparsed_frame_types key retained {} bytes", + key.len() + ); + } + } + + // relay#1680 review (coderabbitai, fleet.rs:857) MUST-FIRE: a disposition of + // `surfaced_and_acked` is stamped when the runtime DECIDES to ack, which is + // not evidence the engine was told — the ack still has to cross a channel + // and a socket. Without the `acks` tallies the report cannot express "the + // broker acked but the ack never left", which is precisely the negative + // this instrument exists to report. + #[test] + fn an_ack_decision_is_distinguishable_from_an_ack_that_reached_the_wire() { + let probe = NodeDeliveryProbe::new(); + let frame = deliver("agent-a", "agent-a-id", "del_ack", 1); + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); + probe.record_disposition(&frame, DeliverDisposition::SurfacedAndAcked); + probe.record_ack_enqueued(); + + let handed_off = probe.snapshot_with_token(true); + assert_eq!(handed_off["dispositions"]["surfaced_and_acked"], 1); + assert_eq!(handed_off["acks"]["enqueued"], 1); + assert_eq!( + handed_off["acks"]["sent"], 0, + "an ack that has not reached the socket must not read as sent" + ); + assert_eq!( + handed_off["acks"]["last_sent_at_ms"], + Value::Null, + "no ack has reached the wire, so there is no last-sent time" + ); + + probe.record_ack_sent(); + let on_the_wire = probe.snapshot_with_token(true); + assert_eq!(on_the_wire["acks"]["sent"], 1); + assert!(on_the_wire["acks"]["last_sent_at_ms"].is_u64()); + + probe.record_ack_enqueue_failed(); + probe.record_ack_send_failed(); + let failed = probe.snapshot_with_token(true); + assert_eq!(failed["acks"]["enqueue_failed"], 1); + assert_eq!(failed["acks"]["send_failed"], 1); + } + + #[test] + fn agent_rows_are_bounded_and_evict_the_stalest_first() { + let probe = NodeDeliveryProbe::new(); + for index in 0..(AGENT_STATS_CAPACITY + 20) { + let frame = deliver( + &format!("agent-{index:04}"), + "ag", + &format!("del_{index}"), + 1, + ); + probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); + } + let snapshot = probe.snapshot_with_token(true); + let rows = snapshot["agents"].as_array().expect("agents"); + assert_eq!(rows.len(), AGENT_STATS_CAPACITY); + + let present = |name: &str| rows.iter().any(|row| row["agent"] == name); + // The newest arrival kept its row... + assert!( + present(&format!("agent-{:04}", AGENT_STATS_CAPACITY + 19)), + "the most recent agent must not be the one refused" + ); + // ...and an early one was evicted to make room. + assert!(!present("agent-0000"), "the stalest row should be evicted"); + + // Every frame is still counted globally regardless of eviction. + assert_eq!( + snapshot["decisions"]["deliver"], + (AGENT_STATS_CAPACITY + 20) as u64 + ); + } + + /// `connected` must come from one flag, not from comparing two counters + /// that can be read skewed. + #[test] + fn connectivity_survives_reconnect_churn() { + let probe = NodeDeliveryProbe::new(); + for _ in 0..5 { + probe.record_connected(); + assert_eq!(probe.snapshot_with_token(true)["connected"], true); + probe.record_disconnected(); + assert_eq!(probe.snapshot_with_token(true)["connected"], false); + } + let snapshot = probe.snapshot_with_token(true); + // The tallies are retained because reconnect churn is itself a signal. + assert_eq!(snapshot["socket"]["connects"], 5); + assert_eq!(snapshot["socket"]["disconnects"], 5); + } + + #[test] + fn absent_timestamps_render_as_null() { + let snapshot = NodeDeliveryProbe::new().snapshot_with_token(false); + assert_eq!(snapshot["frames"]["last_deliver_at_ms"], Value::Null); + assert_eq!(snapshot["socket"]["last_frame_at_ms"], Value::Null); + assert_eq!(snapshot["cursors_published_at_ms"], Value::Null); + assert_eq!(snapshot["connected"], false); + } + + /// `connected` is derived from the probe's own tallies, so the endpoint + /// needs nothing from the runtime event loop to report it. + #[test] + fn connected_tracks_connect_and_disconnect_tallies() { + let probe = NodeDeliveryProbe::new(); + assert_eq!(probe.snapshot_with_token(true)["connected"], false); + probe.record_connected(); + assert_eq!(probe.snapshot_with_token(true)["connected"], true); + probe.record_disconnected(); + assert_eq!(probe.snapshot_with_token(true)["connected"], false); + probe.record_connected(); + assert_eq!(probe.snapshot_with_token(true)["connected"], true); + } + + #[test] + fn published_cursors_are_rendered() { + let probe = NodeDeliveryProbe::new(); + probe.publish_cursors(vec![AgentCursorView { + agent_id: "ag_1".into(), + agent_name: "worker".into(), + acked_up_to_seq: 4, + received_up_to_seq: 6, + has_sequenced_position: true, + }]); + let snapshot = probe.snapshot_with_token(true); + assert_eq!(snapshot["cursors"][0]["agent_name"], "worker"); + assert_eq!(snapshot["cursors"][0]["acked_up_to_seq"], 4); + assert_eq!(snapshot["cursors"][0]["received_up_to_seq"], 6); + assert!(snapshot["cursors_published_at_ms"].is_u64()); + } +} diff --git a/crates/broker/src/runtime/event_loop.rs b/crates/broker/src/runtime/event_loop.rs index 585fd7a15c..7db6849ac4 100644 --- a/crates/broker/src/runtime/event_loop.rs +++ b/crates/broker/src/runtime/event_loop.rs @@ -215,6 +215,10 @@ pub(crate) struct BrokerRuntime { pub(super) fleet_node_name: String, pub(super) node_delivery_token_present: bool, pub(super) node_delivery_connected: bool, + /// `RUST_LOG`-independent introspection for the node-control inbound path, + /// shared with the node-control client task and the HTTP API. See + /// [`crate::node_delivery_probe`]. + pub(super) node_delivery_probe: std::sync::Arc, pub(super) fleet_event_rx: mpsc::Receiver, pub(super) fleet_control_open: bool, /// Independent outbound terminal lane. It never shares the node-control @@ -391,6 +395,7 @@ impl BrokerRuntime { } self.flush_persisted_stores(); + self.publish_fleet_delivery_cursors_if_dirty(); } self.shutdown_runtime().await diff --git a/crates/broker/src/runtime/fleet.rs b/crates/broker/src/runtime/fleet.rs index 18c6770b42..a85f65e614 100644 --- a/crates/broker/src/runtime/fleet.rs +++ b/crates/broker/src/runtime/fleet.rs @@ -7,6 +7,7 @@ use crate::{ }, listen_api::{DeliveryRouteError, ListenApiRequest, SetInboundDeliveryModeOk}, node_control::{delivery_ack, handler_unavailable_result, DeliveryDecision, ReceiptAckability}, + node_delivery_probe::DeliverDisposition, terminal_control::{ TerminalControlCommand, TerminalControlEvent, TerminalFromCloud, TerminalMode, TerminalToCloud, TERMINAL_CLOSE_RESERVE, @@ -860,9 +861,16 @@ impl BrokerRuntime { async fn handle_fleet_deliver(&mut self, deliver: Deliver) { let decision = self.fleet_delivery_book.observe(&deliver); + // Record the book's verdict before acting on it, so a frame that is + // about to be dropped without an ack is still visible over + // `GET /api/node-delivery`. See `crate::node_delivery_probe`. + self.node_delivery_probe + .record_decision(&deliver, &decision); let up_to_seq = match plan_fleet_delivery(decision) { FleetDeliveryPlan::Surface => match self.surface_fleet_deliver(&deliver).await { Ok(FleetDeliverySurfaceOutcome::Acknowledge) => { + self.node_delivery_probe + .record_disposition(&deliver, DeliverDisposition::SurfacedAndAcked); self.fleet_delivery_book.commit_delivered(&deliver) } Ok(FleetDeliverySurfaceOutcome::AcknowledgeAfterEcho) => { @@ -881,14 +889,20 @@ impl BrokerRuntime { // `try_inject_pending_relay_message` / // `insert_and_attempt_delivery`), so there is nothing left // to record here — see relay#1543. + self.node_delivery_probe + .record_disposition(&deliver, DeliverDisposition::Injected); self.fleet_delivery_book.commit_received(&deliver); return; } Ok(FleetDeliverySurfaceOutcome::HoldForManualFlush) => { + self.node_delivery_probe + .record_disposition(&deliver, DeliverDisposition::HeldForManualFlush); self.fleet_delivery_book.commit_received(&deliver); return; } Err(error) => { + self.node_delivery_probe + .record_disposition(&deliver, DeliverDisposition::SurfaceFailed); tracing::warn!( target = "relay_broker::fleet", agent = %deliver.agent, @@ -900,12 +914,30 @@ impl BrokerRuntime { return; } }, - FleetDeliveryPlan::Acknowledge(up_to_seq) => up_to_seq, + FleetDeliveryPlan::Acknowledge(up_to_seq) => { + self.node_delivery_probe + .record_disposition(&deliver, DeliverDisposition::AckedWithoutSurfacing); + up_to_seq + } FleetDeliveryPlan::RejectWithoutAck => { - let reason = match decision { - DeliveryDecision::Gap { .. } => "sequence gap; frame not placeable", - _ => "conflicting agent identity", + // `Gap` and `IdentityReject` share this arm but are different + // diagnoses, so the endpoint must not collapse them: a gap + // means the book could not place a frame the agent never saw, + // an identity reject means the frame was addressed to a + // retired incarnation. Keep the disposition aligned with the + // reason logged below. + let (reason, disposition) = match decision { + DeliveryDecision::Gap { .. } => ( + "sequence gap; frame not placeable", + DeliverDisposition::RejectedSequenceGap, + ), + _ => ( + "conflicting agent identity", + DeliverDisposition::RejectedIdentity, + ), }; + self.node_delivery_probe + .record_disposition(&deliver, disposition); tracing::warn!( target = "relay_broker::fleet", agent = %deliver.agent, @@ -919,13 +951,50 @@ impl BrokerRuntime { return; } }; - let _ = self + // The ack is handed to the node-control task, which owns the socket. + // This loop must not await the wire, so `surfaced_and_acked` / + // `acked_without_surfacing` above can only mean "the broker decided to + // acknowledge" — not "the engine was told". The probe therefore tallies + // the handoff here and the wire write in the socket task, so a reader + // can tell an ack the engine received from one that died in between. + match self .fleet_control_tx .send(FleetControlCommand::Send(delivery_ack( - deliver.agent, + deliver.agent.clone(), up_to_seq, ))) - .await; + .await + { + Ok(()) => self.node_delivery_probe.record_ack_enqueued(), + Err(_) => { + self.node_delivery_probe.record_ack_enqueue_failed(); + tracing::warn!( + target = "relay_broker::fleet", + agent = %deliver.agent, + delivery_id = %deliver.delivery_id, + up_to_seq, + "node control is gone; delivery ack was never queued" + ); + } + } + } + + /// Republish the delivery book's cursors into the shared probe when the + /// book moved, so `GET /api/node-delivery` can report them without posting + /// a request to this event loop. A stale `cursors_published_at_ms` next to + /// a climbing frame counter is itself the signal that this loop has wedged. + /// + /// Driven by the book's dirty flag from one place in the event loop — + /// alongside `flush_persisted_stores` — rather than from the deliver path. + /// Publishing only on delivery meant a worker confirmation, manual flush, + /// registration, identity rebind, or release could advance the book and + /// leave the endpoint serving the previous acknowledgement indefinitely, + /// until some later frame happened to arrive. + pub(super) fn publish_fleet_delivery_cursors_if_dirty(&mut self) { + if self.fleet_delivery_book.take_cursor_dirty() { + self.node_delivery_probe + .publish_cursors(self.fleet_delivery_book.cursor_views()); + } } /// Surface a node `deliver` frame by branching on its payload `type`: diff --git a/crates/broker/src/runtime/init.rs b/crates/broker/src/runtime/init.rs index 7d907f67c0..b844627f90 100644 --- a/crates/broker/src/runtime/init.rs +++ b/crates/broker/src/runtime/init.rs @@ -354,6 +354,9 @@ pub(crate) async fn run_init(cmd: InitCommand, telemetry: TelemetryClient) -> Re let (terminal_event_tx, terminal_event_rx) = mpsc::channel::(1024); let node_delivery_token_present = node_token.is_some(); + // Shared by node-control, runtime, and the independent diagnostic API. + let node_delivery_probe = + std::sync::Arc::new(crate::node_delivery_probe::NodeDeliveryProbe::new()); if !local_only { tokio::spawn(crate::node_control::run_node_control_client( crate::node_control::FleetControlConfig { @@ -365,6 +368,7 @@ pub(crate) async fn run_init(cmd: InitCommand, telemetry: TelemetryClient) -> Re token_minter, session_token: Some(session_node_token.clone()), read_idle_timeout: None, + probe: Some(node_delivery_probe.clone()), }, fleet_control_rx, fleet_event_tx, @@ -471,6 +475,7 @@ pub(crate) async fn run_init(cmd: InitCommand, telemetry: TelemetryClient) -> Re node_name: session_node_name, node_token: session_node_token, persist: paths.persist, + node_delivery_probe: node_delivery_probe.clone(), }); { let mut ready = relay_ready_state.write().await; @@ -763,6 +768,7 @@ pub(crate) async fn run_init(cmd: InitCommand, telemetry: TelemetryClient) -> Re fleet_control_tx, fleet_node_name, node_delivery_token_present, + node_delivery_probe, node_delivery_connected: false, fleet_event_rx, fleet_control_open: true, diff --git a/crates/broker/src/runtime/tests.rs b/crates/broker/src/runtime/tests.rs index 54c5502c9d..63939bba67 100644 --- a/crates/broker/src/runtime/tests.rs +++ b/crates/broker/src/runtime/tests.rs @@ -630,6 +630,9 @@ fn worker_event_runtime_fixture( fleet_control_tx, fleet_node_name: "test-node".to_string(), node_delivery_token_present: true, + node_delivery_probe: std::sync::Arc::new( + crate::node_delivery_probe::NodeDeliveryProbe::new(), + ), node_delivery_connected: true, fleet_event_rx, fleet_control_open: true, @@ -2272,6 +2275,133 @@ async fn terminal_disposition_helpers_remove_withheld_fleet_ack_state() { // Full runtime/channel companion for the terminal-disposition coverage above. // Each real disposal path removes the pending delivery first; a late matching +/// relay#1680 review (P2, codex + cubic). The deferred (echo-confirmed) ACK +/// advances `acked_up_to_seq` long after the deliver frame was handled. While +/// the cursor snapshot was published only from `handle_fleet_deliver`, that +/// advance was invisible: `GET /api/node-delivery` kept serving the old ACK +/// until some later frame happened to arrive. Publication now runs off the +/// book's dirty flag once per event-loop turn, so the confirmation surfaces. +/// relay#1680 review (coderabbitai, fleet.rs:857) MUST-FIRE. +/// +/// `acked_without_surfacing` is stamped before the ack is handed to the +/// node-control task. When that task is gone the ack goes nowhere and the +/// engine will redeliver, but the disposition still reads as an acknowledgement +/// — the instrument reporting a success that did not happen. The `acks` +/// tallies are what separate the two, and they are only worth anything if the +/// runtime actually stops swallowing the channel error. +#[tokio::test] +async fn an_ack_that_never_left_the_runtime_is_reported_as_such() { + let worker_name = "agent-a"; + let registry = make_worker_registry_with_worker(worker_name).await; + let mut fixture = worker_event_runtime_fixture(registry, HashMap::new()); + + let deliver = withheld_ack_for("del_ack_enqueue_failed"); + // Seed the book so the frame below is a duplicate: that plans a bare + // `Acknowledge`, which is the shortest path to the ack send. + fixture + .runtime + .fleet_delivery_book + .bind_authoritative_identity(deliver.agent.clone(), deliver.agent_id.clone()); + fixture + .runtime + .fleet_delivery_book + .commit_delivered(&deliver); + + // The node-control task is gone; nothing can receive the ack. + drop(fixture.fleet_control_rx); + + fixture + .runtime + .handle_fleet_control_event(crate::node_control::FleetControlEvent::Message( + crate::fleet_wire::RelaycastToBroker::Deliver(deliver.clone()), + )) + .await; + + let snapshot = fixture + .runtime + .node_delivery_probe + .snapshot_with_token(true); + assert_eq!( + snapshot["dispositions"]["acked_without_surfacing"], 1, + "the runtime did decide to acknowledge this frame" + ); + assert_eq!( + snapshot["acks"]["enqueue_failed"], 1, + "the ack never reached the node-control task, and the endpoint must \ + say so rather than leave the disposition reading as a delivered ack" + ); + assert_eq!( + snapshot["acks"]["enqueued"], 0, + "nothing was handed off, so nothing may be tallied as enqueued" + ); + assert_eq!(snapshot["acks"]["sent"], 0); +} + +#[tokio::test] +async fn a_worker_confirmed_ack_becomes_visible_on_the_node_delivery_endpoint() { + let worker_name = "worker-a"; + let registry = make_worker_registry_with_worker(worker_name).await; + let generation = registry.workers[worker_name].generation; + let mut fixture = worker_event_runtime_fixture(registry, HashMap::new()); + + let delivery_id = DeliveryId::new("del_runtime_cursor_publish"); + let deliver = Deliver { + agent: worker_name.to_string(), + agent_id: "worker-a-id".to_string(), + delivery_id: delivery_id.to_string(), + msg_id: format!("evt_{delivery_id}"), + ..withheld_ack_for(delivery_id.as_str()) + }; + + // The state right after an injection: received, ack withheld pending echo. + fixture + .runtime + .fleet_delivery_book + .bind_authoritative_identity(deliver.agent.clone(), deliver.agent_id.clone()); + fixture + .runtime + .fleet_delivery_book + .commit_received(&deliver); + fixture.runtime.publish_fleet_delivery_cursors_if_dirty(); + + let acked_of = |probe: &crate::node_delivery_probe::NodeDeliveryProbe| { + probe.snapshot_with_token(true)["cursors"][0]["acked_up_to_seq"].clone() + }; + assert_eq!( + acked_of(&fixture.runtime.node_delivery_probe), + serde_json::json!(0), + "the ack is withheld until the worker confirms" + ); + + let mut pending = make_pending_delivery(delivery_id.as_str(), worker_name); + pending.withheld_fleet_ack = Some(deliver.clone()); + fixture + .runtime + .pending_deliveries + .insert(delivery_id.clone(), pending); + + // The worker echoes the injection back: the deferred ACK is released. + fixture + .runtime + .handle_worker_event(delivery_lifecycle_worker_event( + worker_name, + generation, + "delivery_ack", + delivery_id.as_str(), + format!("evt_{}", delivery_id.as_str()).as_str(), + )) + .await; + + // One event-loop turn's post-processing, as `run()` performs it. + fixture.runtime.publish_fleet_delivery_cursors_if_dirty(); + assert_eq!( + acked_of(&fixture.runtime.node_delivery_probe), + serde_json::json!(1), + "a worker-confirmed delivery must advance the published ACK cursor, \ + not leave the endpoint serving the pre-confirmation value" + ); +} + // worker `delivery_ack` is then driven through `BrokerRuntime::handle_worker_event`. // None may produce a fleet-control Send, even though the event reaches the same // branch that releases a successful withheld ACK. diff --git a/packages/harness-driver/src/protocol.ts b/packages/harness-driver/src/protocol.ts index 51b4d7fea4..445ed3e77e 100644 --- a/packages/harness-driver/src/protocol.ts +++ b/packages/harness-driver/src/protocol.ts @@ -291,6 +291,133 @@ export interface BrokerStatus { auth?: BrokerAuthStatus; } +/** Where a `deliver` frame ended up once the broker had acted on it. */ +export type NodeDeliveryDisposition = + | 'injected' + | 'surfaced_and_acked' + | 'held_for_manual_flush' + | 'surface_failed' + | 'acked_without_surfacing' + | 'rejected_identity' + | 'rejected_sequence_gap'; + +/** + * One `deliver` frame the broker observed on `/v1/node/ws`, reduced to + * identifiers. Message bodies are deliberately absent: this report is meant to + * be safe to paste into an issue. + */ +export interface NodeDeliveryRecord { + at_ms: number; + agent: string; + agent_id: string; + delivery_id: string; + msg_id: string; + seq: number; + /** The `type` on the frame's payload, e.g. `dm.received`, `message.created`. */ + payload_type: string; + /** The delivery book's verdict on the frame. */ + decision: 'deliver' | 'duplicate' | 'stale' | 'gap' | 'identity_reject'; + /** Where the frame ended up. `null` while still in flight. */ + disposition: + | 'injected' + | 'surfaced_and_acked' + | 'held_for_manual_flush' + | 'surface_failed' + | 'acked_without_surfacing' + | 'rejected_identity' + | 'rejected_sequence_gap' + | null; +} + +/** + * Per-agent delivery tallies, retained past the FIFO eviction of + * `recent_delivers` so a single deaf agent stays diagnosable on a busy broker. + * + * `delivers_seen` not advancing means the frame never reached this broker; + * advancing while `dispositions.injected` does not means the delivery book + * discarded it, and `decisions` says which way. + */ +export interface NodeDeliveryAgentRow { + agent: string; + agent_id: string; + delivers_seen: number; + decisions: Record<'deliver' | 'duplicate' | 'stale' | 'gap' | 'identity_reject', number>; + dispositions: Record; + last_deliver_at_ms: number | null; + /** Last confirmed delivery to this agent — a deaf agent from a quiet one. */ + last_injected_at_ms: number | null; +} + +/** + * `GET /api/node-delivery` — whether node-control `deliver` frames are reaching + * the broker and what becomes of them. + * + * `socket.text_frames` counts inbound frames *before* deserialization, so a + * `deliver` the broker cannot parse still shows up as having arrived; compare + * it against `frames.deliver` and `socket.parse_failures` to tell "nothing + * arrived" apart from "it arrived and was discarded". + * + * The report is served from shared state rather than the broker's runtime event + * loop. When that loop wedges, the socket counters keep climbing while + * `cursors_published_at_ms` stops advancing. + */ +export interface NodeDeliveryReport { + connected: boolean; + token_present: boolean; + now_ms: number; + socket: { + connects: number; + disconnects: number; + /** Inbound WS text frames, counted before deserialization. */ + text_frames: number; + parse_failures: number; + last_frame_at_ms: number | null; + }; + frames: { + deliver: number; + action_invoke: number; + ping: number; + reply: number; + error: number; + last_deliver_at_ms: number | null; + }; + decisions: Record<'deliver' | 'duplicate' | 'stale' | 'gap' | 'identity_reject', number>; + dispositions: Record; + /** + * Whether the `delivery_ack` the dispositions above imply actually left the + * broker. A disposition is stamped by the runtime when it *decides* to ack; + * the ack is then handed to the socket task, which is where it can still be + * lost. `enqueued` above `sent` means acks are stuck between the two. + */ + acks: { + enqueued: number; + enqueue_failed: number; + sent: number; + send_failed: number; + last_sent_at_ms: number | null; + }; + /** Per-agent rows, retained past the FIFO eviction of `recent_delivers`. */ + agents: NodeDeliveryAgentRow[]; + recent_delivers: NodeDeliveryRecord[]; + /** Frame `type` values the broker could not deserialize, and how often. */ + unparsed_frame_types: Record; + last_parse_failure: { + at_ms: number; + error: string; + frame_type: string | null; + frame_len: number; + } | null; + /** When the runtime last republished `cursors`; stale means a stalled loop. */ + cursors_published_at_ms: number | null; + cursors: Array<{ + agent_id: string; + agent_name: string; + acked_up_to_seq: number; + received_up_to_seq: number; + has_sequenced_position: boolean; + }>; +} + /** A terminally-failed delivery retained in the broker's dead-letter queue. */ export interface DeadLetterInfo { delivery_id: string; diff --git a/tests/relayflows/cases/1678-node-delivery-introspection/case.json b/tests/relayflows/cases/1678-node-delivery-introspection/case.json new file mode 100644 index 0000000000..d82918469f --- /dev/null +++ b/tests/relayflows/cases/1678-node-delivery-introspection/case.json @@ -0,0 +1,21 @@ +{ + "version": 1, + "id": "1678-node-delivery-introspection", + "kind": "feature", + "title": "Report whether node-control deliver frames reach the broker", + "runner": { + "command": ["node", "tests/relayflows/cases/1678-node-delivery-introspection/run.mjs"] + }, + "requirements": ["broker-linux-x64"], + "timeoutSeconds": 900, + "expected": { + "base": { + "outcome": "absent", + "signature": "deliver_frame_arrival_is_unobservable" + }, + "head": { + "outcome": "fixed", + "signature": "deliver_frame_arrival_is_observable" + } + } +} diff --git a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs new file mode 100644 index 0000000000..f1c6b3dcca --- /dev/null +++ b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs @@ -0,0 +1,487 @@ +/** + * relay#1678 — whether a node-control `deliver` frame reaches the broker is + * not observable on a running broker. + * + * A silent agent has one first question: did the engine's `deliver` frame get + * here at all? On the base broker nothing can answer it. The delivery book has + * no introspection, and every step of the inbound path reports itself only + * through `tracing` — so a broker started without `RUST_LOG` (which is how + * brokers actually run) emits nothing. The only way to get evidence is to + * restart the broker with logging on, which discards the in-memory cursors + * that hold the evidence. That is the gap this case pins. + * + * Base: `GET /api/node-delivery` does not exist. Arrival is unobservable. + * Head: the endpoint reports frame counters, the delivery book's verdict on + * each frame, and where the frame ended up. + * + * The broker here is started with RUST_LOG DELIBERATELY UNSET. An instrument + * that only works when logging is already on would not have helped, so the + * case proves the endpoint under the condition it was built for. + * + * The head arm is not satisfied by the endpoint merely answering. It takes a + * control read first — node control connected, the agent registered and idle, + * no message sent — and requires the deliver count to be zero there and + * non-zero only after a real DM crosses a real engine. Without that control a + * counter stuck at 1, or one incremented by registration traffic, would pass. + */ +import { execFileSync, spawn } from 'node:child_process'; +import { mkdtemp, mkdir, readFile, rm, writeFile } from 'node:fs/promises'; +import { createServer } from 'node:net'; +import { tmpdir } from 'node:os'; +import path from 'node:path'; +import process from 'node:process'; +import { fileURLToPath } from 'node:url'; +import { ensureEngine, startEngine } from '../../shared/relaycast-engine.mjs'; + +const CASE_ID = '1678-node-delivery-introspection'; +const AGENT = 'deliver-probe-agent'; +const BROKER_API_KEY = 'rk_proof_broker_api_key'; +/** A readiness probe either answers immediately or the peer is not ready. */ +const READINESS_TIMEOUT_MS = 2_000; +/** Normal API calls: generous, but never unbounded. */ +const REQUEST_TIMEOUT_MS = 15_000; +const ENGINE_READY_TIMEOUT_MS = 60_000; + +/** + * The endpoint's closed vocabularies, mirrored from `NodeDeliveryReport` in + * `packages/harness-driver/src/protocol.ts`. Reported values are matched + * against these and the matching entry from *here* is what the artifact + * records, so the result file never carries text chosen by the peer. + */ +const DECISIONS = ['deliver', 'duplicate', 'stale', 'gap', 'identity_reject']; +const DISPOSITIONS = [ + 'injected', + 'surfaced_and_acked', + 'held_for_manual_flush', + 'surface_failed', + 'acked_without_surfacing', + 'rejected_identity', + 'rejected_sequence_gap', +]; +/** + * Payload discriminators a DM through the engine can legitimately carry. Unlike + * the two above this is the engine's vocabulary rather than the broker's, so an + * unrecognized value is reported as such rather than failing the case — the + * case asserts nothing about it. + */ +const PAYLOAD_TYPES = ['dm.received', 'dm.created', 'message.created', 'message.received']; + +const targetDir = requiredValue('RELAY_PR_PROOF_TARGET_DIR'); +const harnessDir = requiredValue('RELAY_PR_PROOF_HARNESS_DIR'); +const binaryPath = requiredValue('RELAY_PR_PROOF_BROKER_BINARY'); +const resultPath = requiredValue('RELAY_PR_PROOF_RESULT_PATH'); +const arm = requiredValue('RELAY_PR_PROOF_ARM'); +if (arm !== 'base' && arm !== 'head') { + throw new Error(`RELAY_PR_PROOF_ARM must be base or head, received ${JSON.stringify(arm)}.`); +} +const expectedSha = + arm === 'base' ? process.env.RELAY_PR_PROOF_BASE_SHA : process.env.RELAY_PR_PROOF_HEAD_SHA; +if (!expectedSha) throw new Error(`Missing expected ${arm} SHA.`); +const targetSha = execFileSync('git', ['-C', targetDir, 'rev-parse', 'HEAD'], { + encoding: 'utf8', +}).trim(); +if (targetSha !== expectedSha) { + throw new Error(`Target checkout ${targetSha} does not match exact ${arm} SHA ${expectedSha}.`); +} +const runnerPath = fileURLToPath(import.meta.url); +if (!isWithin(harnessDir, runnerPath)) { + throw new Error('The RelayFlow runner must execute from the exact-head harness checkout.'); +} + +const workDir = await mkdtemp(path.join(tmpdir(), 'relayflow-1678-')); +const engineDir = path.join(workDir, 'engine'); +const stateDir = path.join(workDir, 'state'); +await mkdir(stateDir, { recursive: true }); + +const diag = []; +const log = (line) => diag.push(String(line)); +let engine; +let broker; + +try { + const serveBin = await ensureEngine(engineDir, log); + // `freePort` reserves an ephemeral port and closes it again, so the engine + // re-binds a port that was briefly free — another process on a busy CI box + // can take it in between and the engine dies on bind. The engine's serve + // binary takes an explicit --port, so it cannot be handed 0 the way the + // broker is; instead treat a bind failure as retryable and try a fresh port. + const { child: startedEngine, url: engineUrl } = await startEngineOnFreePort(serveBin); + engine = startedEngine; + const eng = engineClient(engineUrl); + + const ws = await eng('POST', '/v1/workspaces', { name: 'relayflow-1678' }); + const workspaceKey = ws.body?.data?.api_key; + if (!workspaceKey) { + throw new Error(`workspace create failed: ${JSON.stringify(ws.body).slice(0, 300)}`); + } + const wsAuth = { authorization: `Bearer ${workspaceKey}` }; + + const nodeId = `node_relayflow_1678_${Date.now()}`; + const nodeReg = await eng( + 'POST', + '/v1/nodes', + { + node_id: nodeId, + name: 'relayflow-1678-node', + kind: 'ws', + role: 'broker', + capabilities: [], + max_agents: 8, + version: 'relayflow/1678', + }, + wsAuth + ); + const nodeToken = nodeReg.body?.data?.token; + if (!nodeToken) throw new Error(`node mint failed: ${JSON.stringify(nodeReg.body).slice(0, 300)}`); + + broker = spawn( + binaryPath, + ['init', '--api-port', '0', '--api-bind', '127.0.0.1', '--state-dir', stateDir], + { + cwd: workDir, + env: { + PATH: process.env.PATH, + HOME: workDir, + TMPDIR: process.env.TMPDIR ?? '/tmp', + RELAY_BASE_URL: engineUrl, + RELAYCAST_BASE_URL: engineUrl, + RELAY_API_KEY: workspaceKey, + RELAY_WORKSPACE_KEY: workspaceKey, + RELAY_NODE_TOKEN: nodeToken, + RELAY_NODE_ID: nodeId, + RELAY_BROKER_API_KEY: BROKER_API_KEY, + RELAY_SKIP_TELEMETRY: '1', + // RUST_LOG is deliberately absent — see the file header. + }, + stdio: ['ignore', 'pipe', 'pipe'], + } + ); + let brokerOutput = ''; + broker.stdout.on('data', (d) => { + brokerOutput += d; + log(`[broker] ${d}`); + }); + broker.stderr.on('data', (d) => { + brokerOutput += d; + log(`[broker] ${d}`); + }); + + // The broker publishes its bound port to a file; every later request is built + // from it. Only the port is taken, and only after it validates as a number on + // the loopback host — the origin is then rebuilt from constants rather than + // returning the file's own string. Reusing that string would let anything else + // it carried (a userinfo segment, a path, a query) ride into every request + // built by string concatenation below. + const brokerUrl = await waitFor(async () => { + if (broker.exitCode !== null) throw new Error(`broker exited early with code ${broker.exitCode}`); + const connection = JSON.parse(await readFile(path.join(stateDir, 'connection.json'), 'utf8')); + const url = new URL(connection.url); + const port = Number(url.port); + if (url.protocol !== 'http:' || url.hostname !== '127.0.0.1' || !Number.isInteger(port) || port <= 0) { + throw new Error(`bad connection url ${connection.url}`); + } + return `http://127.0.0.1:${port}`; + }, 'the broker connection file to publish its bound API port'); + const api = brokerClient(brokerUrl); + await waitFor(() => api('GET', '/api/status').then(() => true), 'the broker API to answer'); + + // A live worker, registered with the real engine and idle. + await api('POST', '/api/spawn', { name: AGENT, cli: 'cat', transport: 'pty' }); + await waitFor(async () => { + const row = await eng('GET', '/v1/agents', undefined, wsAuth); + const list = row.body?.data?.agents ?? row.body?.data ?? []; + return Array.isArray(list) && list.some((entry) => entry.name === AGENT); + }, 'the agent to register with the real engine'); + + const probe = () => api('GET', '/api/node-delivery'); + const first = await probe().catch((error) => ({ __error: String(error) })); + + let outcome; + let signature; + let details; + + if (first.__error) { + // Base: no endpoint. Confirm the absence is specific to this route and not + // a dead broker, or the arm would "pass" against a broker that never came + // up at all. + if (!/\b404\b/.test(first.__error)) { + throw new Error(`Expected a 404 from the introspection route, got: ${first.__error}`); + } + const status = await api('GET', '/api/status'); + if (typeof status.agent_count !== 'number') { + throw new Error( + `Control failed: /api/status did not answer normally: ${JSON.stringify(status).slice(0, 200)}` + ); + } + // And the base broker really is mute, which is why nothing else can answer. + outcome = 'absent'; + signature = 'deliver_frame_arrival_is_unobservable'; + // The 404 is what the check above asserted; record that, not the broker's + // echo of it, so no response text reaches the artifact. + details = + `The base broker has no GET /api/node-delivery (the route answered 404), while ` + + `GET /api/status answers normally with ${Number(status.agent_count)} agent(s). With RUST_LOG unset ` + + `the broker emitted ${brokerOutput.length} bytes total on stdout+stderr, so whether a ` + + `deliver frame reached it cannot be established without a restart that destroys the cursors.`; + } else { + // Head. Control first: connected, agent registered and idle, nothing sent. + await waitFor(async () => (await probe()).connected === true, 'node control to connect'); + await sleep(2_000); + const before = await probe(); + if (before.frames.deliver !== 0) { + throw new Error( + `Control failed: ${before.frames.deliver} deliver frame(s) counted before any message was sent. ` + + 'A counter that is already non-zero here proves nothing about the DM below.' + ); + } + if (before.socket.text_frames <= 0) { + throw new Error( + `Control failed: the socket counted ${before.socket.text_frames} inbound frames while ` + + 'node control reports connected, so the frame counter is not wired to the socket.' + ); + } + + const sender = await eng('POST', '/v1/agents', { name: 'proof-sender', type: 'agent' }, wsAuth); + const senderToken = sender.body?.data?.token; + if (!senderToken) { + throw new Error(`sender create failed: ${JSON.stringify(sender.body).slice(0, 300)}`); + } + await eng( + 'POST', + '/v1/dm', + { to: AGENT, text: 'deliver frame probe' }, + { authorization: `Bearer ${senderToken}` } + ); + + const after = await waitFor(async () => { + const current = await probe(); + return current.frames.deliver > 0 ? current : null; + }, 'the deliver frame to be counted by the broker'); + + // Arrival alone is half the question; the endpoint must also say where the + // frame went, or it cannot answer "at what point did it stop". + const entry = after.recent_delivers?.find((row) => row.msg_id && row.decision); + if (!entry) { + throw new Error(`No recent delivery was recorded: ${JSON.stringify(after).slice(0, 400)}`); + } + if (entry.agent !== AGENT) { + throw new Error(`Recorded delivery names ${entry.agent}, expected ${AGENT}.`); + } + if (!entry.disposition) { + throw new Error(`The frame was counted but its outcome was not recorded: ${JSON.stringify(entry)}.`); + } + if (after.socket.text_frames <= before.socket.text_frames) { + throw new Error( + `Socket frame counter did not advance across the DM ` + + `(${before.socket.text_frames} -> ${after.socket.text_frames}).` + ); + } + + outcome = 'fixed'; + signature = 'deliver_frame_arrival_is_observable'; + // Nothing the broker said is echoed into the artifact verbatim. Each value + // is matched against the endpoint's own closed vocabulary and the LOCAL + // literal is what gets written — so an outcome this case does not know + // about fails loudly here instead of being pasted through into a PR. The + // agent name is the constant this case asserted equal two checks above. + details = + `GET /api/node-delivery answered with RUST_LOG unset (the broker emitted ${brokerOutput.length} ` + + `bytes on stdout+stderr for the whole run). Deliver frames counted 0 before any message was ` + + `sent — with node control connected, the agent registered and idle, and ` + + `${Number(before.socket.text_frames)} inbound socket frames already tallied — and ` + + `${Number(after.frames.deliver)} after one real DM through the engine. The frame is reported ` + + `as agent=${AGENT} seq=${Number(entry.seq)} ` + + `payload_type=${oneOf(entry.payload_type, PAYLOAD_TYPES) ?? '(unrecognized)'} ` + + `decision=${required(oneOf(entry.decision, DECISIONS), 'decision', entry.decision)} ` + + `disposition=${required(oneOf(entry.disposition, DISPOSITIONS), 'disposition', entry.disposition)}, ` + + `so both "did it arrive" and "where did it stop" are answerable without restarting the broker.`; + } + + await mkdir(path.dirname(resultPath), { recursive: true }); + await writeFile( + resultPath, + `${JSON.stringify({ version: 1, caseId: CASE_ID, arm, outcome, signature, details })}\n`, + 'utf8' + ); + process.stdout.write(`${signature}\n`); +} catch (error) { + process.stderr.write(`${diag.join('').slice(-12_000)}\n`); + throw error; +} finally { + for (const child of [broker, engine]) await stop(child); + await rm(workDir, { recursive: true, force: true }); +} + +/** + * Start the engine, retrying on a fresh port if it fails to come up. + * + * Distinguishes "this port was taken" (retry) from "the engine is broken" + * (fail loudly) by requiring the process to both stay alive and answer HTTP. + */ +async function startEngineOnFreePort(serveBin, attempts = 5) { + let last; + for (let attempt = 1; attempt <= attempts; attempt += 1) { + const port = await freePort(); + const url = `http://127.0.0.1:${port}`; + const child = await startEngine(serveBin, engineDir, port, log); + try { + await waitFor( + async () => { + if (child.exitCode !== null) { + throw new Error(`engine exited with code ${child.exitCode}`); + } + // `fetch` resolves for any HTTP status, so "something answered" is + // not "the engine answered" — the port was free a moment ago and any + // process could hold it now. Require the engine's own /health body. + const res = await fetchBounded(`${url}/health`, {}, READINESS_TIMEOUT_MS); + if (!res.ok) throw new Error(`/health answered ${res.status}`); + const body = await res.json().catch(() => null); + if (body?.ok !== true) { + throw new Error(`/health is not the Relaycast engine: ${JSON.stringify(body)?.slice(0, 120)}`); + } + return true; + }, + `the Relaycast engine to accept connections on ${port}`, + ENGINE_READY_TIMEOUT_MS + ); + return { child, url }; + } catch (error) { + last = error; + log(`engine did not come up on ${port} (attempt ${attempt}/${attempts}): ${error.message}`); + await stop(child); + } + } + throw new Error(`The Relaycast engine never came up: ${last?.message ?? 'unknown failure'}.`); +} + +/** + * `fetch` with an explicit deadline. + * + * Node's fetch has no default timeout, so a peer that completes the TCP + * handshake and then never responds leaves the promise pending forever. The + * enclosing `waitFor` cannot rescue that — it awaits this call — so the case + * would hang to the dispatcher's 900s cap and report an infrastructure failure + * instead of a result. + */ +async function fetchBounded(url, init, timeoutMs) { + return fetch(url, { ...init, signal: AbortSignal.timeout(timeoutMs) }); +} + +/** + * Reduce a value the broker reported over HTTP to something safe to embed in + * the result artifact. + * + * The result file is read back by the dispatcher and pasted into a PR, and + * these fields originate from the engine's frame, not from this case. Bound the + * length and keep only printable ASCII, so a hostile or merely malformed + * discriminator cannot inject newlines, control characters or unbounded text + * into the record. + */ +function safeField(value, limit = 64) { + return String(value) + .replace(/[^\x20-\x7e]/g, '?') + .slice(0, limit); +} + +/** The matching entry from `allowed`, or undefined. Never the caller's copy. */ +function oneOf(value, allowed) { + return allowed.find((candidate) => candidate === value); +} + +/** Fail the case on a value outside the endpoint's own documented vocabulary. */ +function required(matched, field, reported) { + if (matched === undefined) { + throw new Error( + `The endpoint reported a ${field} outside its documented vocabulary: ${safeField(reported)}. ` + + 'Either the broker gained an outcome this case does not know about, or the response is not ' + + 'from the endpoint under test — neither is a pass.' + ); + } + return matched; +} + +function requiredValue(name) { + const value = process.env[name]?.trim(); + if (!value) throw new Error(`Missing required environment variable ${name}.`); + return value; +} +function isWithin(root, candidate) { + const rel = path.relative(path.resolve(root), path.resolve(candidate)); + return rel !== '' && !rel.startsWith('..') && !path.isAbsolute(rel); +} +function sleep(ms) { + return new Promise((resolve) => setTimeout(resolve, ms)); +} +function freePort() { + return new Promise((resolve, reject) => { + const probe = createServer(); + probe.unref(); + probe.on('error', reject); + probe.listen(0, '127.0.0.1', () => { + const { port } = probe.address(); + probe.close(() => resolve(port)); + }); + }); +} +function engineClient(baseUrl) { + return async (method, route, body, headers = {}) => { + const res = await fetchBounded( + `${baseUrl}${route}`, + { + method, + headers: { 'content-type': 'application/json', ...headers }, + ...(body === undefined ? {} : { body: JSON.stringify(body) }), + }, + REQUEST_TIMEOUT_MS + ); + const text = await res.text(); + let parsed = {}; + try { + parsed = text ? JSON.parse(text) : {}; + } catch { + parsed = { raw: text }; + } + return { status: res.status, body: parsed }; + }; +} +function brokerClient(baseUrl) { + return async (method, route, body) => { + const res = await fetchBounded( + `${baseUrl}${route}`, + { + method, + headers: { + 'content-type': 'application/json', + authorization: `Bearer ${BROKER_API_KEY}`, + }, + ...(body === undefined ? {} : { body: JSON.stringify(body) }), + }, + REQUEST_TIMEOUT_MS + ); + const text = await res.text(); + if (!res.ok) throw new Error(`${method} ${route} -> ${res.status} ${text.slice(0, 300)}`); + return text ? JSON.parse(text) : {}; + }; +} +async function waitFor(check, what, timeoutMs = 90_000) { + const deadline = Date.now() + timeoutMs; + let last; + while (Date.now() < deadline) { + try { + const value = await check(); + if (value) return value; + } catch (error) { + last = error; + } + await sleep(250); + } + throw new Error(`Timed out waiting for ${what}${last ? `: ${last.message}` : ''}.`); +} +async function stop(child) { + if (!child || child.exitCode !== null) return; + child.kill('SIGTERM'); + await Promise.race([ + new Promise((resolve) => child.once('exit', resolve)), + sleep(5_000).then(() => child.kill('SIGKILL')), + ]); +} diff --git a/tests/relayflows/shared/relaycast-engine.mjs b/tests/relayflows/shared/relaycast-engine.mjs new file mode 100644 index 0000000000..8469425bb3 --- /dev/null +++ b/tests/relayflows/shared/relaycast-engine.mjs @@ -0,0 +1,120 @@ +/** + * Bring up a REAL Relaycast engine, not a stand-in. + * + * `@relaycast/engine` publishes `dist/bin/serve.js`, which runs standalone + * against a local sqlite file. That gives cases authentic registration, + * identity, node-control and delivery semantics — the things an in-case fake + * would otherwise get to decide for itself. + * + * The engine's `better-sqlite3` dependency ships no prebuilt binary in its + * tarball, so installation may need to fetch one or compile it. That is why + * `ensureEngine` reports its own failure precisely: an engine that cannot be + * installed is an infrastructure fault, and a case must say so rather than + * silently degrade into proving nothing. + * + * Shared by every RelayFlow case that needs a real engine. It previously lived + * as a per-case copy; `ENGINE_VERSION` and the fragile binding-normalisation + * fallback below are exactly the things that must not silently diverge between + * cases, so they live here once. + */ +import { execFile as execFileCb, spawn } from 'node:child_process'; +import { mkdir, writeFile } from 'node:fs/promises'; +import path from 'node:path'; +import { promisify } from 'node:util'; + +const execFile = promisify(execFileCb); +export const ENGINE_VERSION = '8.2.2'; +const SERVE_BIN = 'node_modules/@relaycast/engine/dist/bin/serve.js'; + +/** + * Bounds on the two subprocesses that reach the network or a compiler. + * + * Without these, a stalled registry or a silently-hanging native build never + * rejects, so `ensureEngine` never returns and the case burns the dispatcher's + * full 900s cap before reporting anything. That reads as a timed-out case + * rather than the infrastructure failure it is. A bounded reject fails fast + * and legibly instead. + */ +const INSTALL_TIMEOUT_MS = 420_000; +const REBUILD_TIMEOUT_MS = 300_000; + +/** Install the engine into `dir` and return the path to its serve binary. */ +export async function ensureEngine(dir, log = () => {}) { + await mkdir(dir, { recursive: true }); + await writeFile( + path.join(dir, 'package.json'), + `${JSON.stringify({ name: 'relayflow-engine-host', private: true, version: '0.0.0' }, null, 2)}\n`, + 'utf8' + ); + log(`installing @relaycast/engine@${ENGINE_VERSION}`); + await run( + 'npm', + ['install', `@relaycast/engine@${ENGINE_VERSION}`, '--no-audit', '--no-fund'], + { cwd: dir, timeout: INSTALL_TIMEOUT_MS }, + 'npm install' + ); + + // `bindings` resolves the native addon from build/Release. Newer + // better-sqlite3 ships prebuilds/ instead, and the engine pins a version that + // ships neither, so normalise whichever layout we ended up with and fall back + // to compiling. Doing this here keeps the failure legible instead of + // surfacing as "Could not locate the bindings file" from deep inside startup. + const nested = path.join(dir, 'node_modules/@relaycast/engine/node_modules/better-sqlite3'); + const top = path.join(dir, 'node_modules/better-sqlite3'); + for (const root of [nested, top]) { + await normaliseSqliteBindings(root, log); + } + return path.join(dir, SERVE_BIN); +} + +/** `execFile` with a bounded timeout and an error that names what timed out. */ +async function run(command, args, options, label) { + try { + return await execFile(command, args, { maxBuffer: 32 * 1024 * 1024, ...options }); + } catch (error) { + if (error?.killed && error?.signal) { + throw new Error( + `${label} exceeded ${Math.round((options.timeout ?? 0) / 1000)}s and was killed (${error.signal}). ` + + 'Treat this as an infrastructure fault, not a case result.' + ); + } + throw error; + } +} + +async function normaliseSqliteBindings(root, log) { + const { existsSync } = await import('node:fs'); + if (!existsSync(root)) return; + const target = path.join(root, 'build', 'Release', 'better_sqlite3.node'); + if (existsSync(target)) return; + const prebuilt = path.join(root, 'prebuilds', `${process.platform}-${process.arch}.node`); + if (existsSync(prebuilt)) { + await mkdir(path.dirname(target), { recursive: true }); + const { copyFile } = await import('node:fs/promises'); + await copyFile(prebuilt, target); + log(`used prebuilt sqlite binding for ${process.platform}-${process.arch}`); + return; + } + log('compiling better-sqlite3 from source'); + await run( + 'npx', + ['--yes', 'node-gyp', 'rebuild'], + { cwd: root, timeout: REBUILD_TIMEOUT_MS }, + 'node-gyp rebuild' + ); +} + +/** Start the engine on `port` against a fresh sqlite db under `dir`. */ +export async function startEngine(serveBin, dir, port, onLog = () => {}) { + const child = spawn( + process.execPath, + [serveBin, '--port', String(port), '--db', path.join(dir, 'relaycast.db'), '--env', 'test'], + { + cwd: dir, + stdio: ['ignore', 'pipe', 'pipe'], + } + ); + child.stdout.on('data', (d) => onLog(`[engine] ${d}`)); + child.stderr.on('data', (d) => onLog(`[engine] ${d}`)); + return child; +} From 8c5ea3b4150f4a21fa8d801b3a937fb0d616a04c Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:41:32 +0200 Subject: [PATCH 02/13] fix(broker): keep peer values out of diagnostic parse errors Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- crates/broker/src/node_delivery_probe.rs | 23 ++++++++++++++++++----- 1 file changed, 18 insertions(+), 5 deletions(-) diff --git a/crates/broker/src/node_delivery_probe.rs b/crates/broker/src/node_delivery_probe.rs index 470a632bf3..89fd2a74cb 100644 --- a/crates/broker/src/node_delivery_probe.rs +++ b/crates/broker/src/node_delivery_probe.rs @@ -55,7 +55,7 @@ const RECENT_CAPACITY: usize = 32; /// engine could otherwise turn this map into an unbounded allocation. const UNPARSED_TYPE_CAPACITY: usize = 16; -/// Cap on a retained serde error string. +#[cfg(test)] const ERROR_EXCERPT_LIMIT: usize = 300; /// Cap on per-agent rows. A broker hosts tens of agents; this bounds the map @@ -349,13 +349,14 @@ impl NodeDeliveryProbe { /// Called when a text frame failed to deserialize into `ServerToNode`. /// `raw` is inspected only to recover the `type` discriminator; it is /// never retained. - pub(crate) fn record_parse_failure(&self, error: &str, raw: &str) { + pub(crate) fn record_parse_failure(&self, _error: &str, raw: &str) { self.counters.parse_failures.fetch_add(1, Ordering::Relaxed); let frame_type = serde_json::from_str::(raw) .ok() .and_then(|value| value.get("type").and_then(Value::as_str).map(bounded)); - let mut error = error.to_string(); - truncate_on_char_boundary(&mut error, ERROR_EXCERPT_LIMIT); + // Serde errors can quote invalid peer values, including a message body. + // Retain a local category only; frame type and length carry safe context. + let error = "invalid node-control frame".to_string(); let Ok(mut retained) = self.retained.lock() else { return; }; @@ -906,10 +907,22 @@ mod tests { // Truncated on a boundary, and still bounded in BYTES — taking N chars // instead would admit up to 4x the limit. assert!(recorded.len() <= ERROR_EXCERPT_LIMIT); - assert!(long_error.starts_with(recorded)); + assert_eq!(recorded, "invalid node-control frame"); + assert!(!recorded.contains("é")); assert_eq!(snapshot["socket"]["parse_failures"], 1); } + #[test] + fn parse_failure_does_not_echo_invalid_peer_values_from_serde() { + let raw = r#"{"type":"deliver","v":1,"seq":"PRIVATE_BODY_IN_INVALID_VALUE"}"#; + let error = serde_json::from_str::(raw).unwrap_err(); + let probe = NodeDeliveryProbe::new(); + probe.record_parse_failure(&error.to_string(), raw); + let report = probe.snapshot_with_token(true).to_string(); + assert!(!report.contains("PRIVATE_BODY_IN_INVALID_VALUE")); + assert!(report.contains("invalid node-control frame")); + } + #[test] fn truncation_keeps_whole_characters_and_the_byte_bound() { let mut value = format!("a{}", "é".repeat(400)); From f2551d7befb178d77cb6eee7914d5259c1f1c5cb Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:50:25 +0200 Subject: [PATCH 03/13] fix(broker): label pending handoff without claiming injection Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- crates/broker/src/listen_api.rs | 7 +- crates/broker/src/node_delivery_probe.rs | 65 +++++++++---------- crates/broker/src/runtime/fleet.rs | 2 +- packages/harness-driver/src/protocol.ts | 8 +-- .../1678-node-delivery-introspection/run.mjs | 2 +- 5 files changed, 43 insertions(+), 41 deletions(-) diff --git a/crates/broker/src/listen_api.rs b/crates/broker/src/listen_api.rs index e10f0051c0..6663acaf60 100644 --- a/crates/broker/src/listen_api.rs +++ b/crates/broker/src/listen_api.rs @@ -4040,7 +4040,7 @@ mod auth_tests { &deliver, &crate::node_control::DeliveryDecision::Deliver { up_to_seq: 7 }, ); - probe.record_disposition(&deliver, DeliverDisposition::Injected); + probe.record_disposition(&deliver, DeliverDisposition::QueuedForInjection); let response = router .oneshot( @@ -4060,7 +4060,10 @@ mod auth_tests { assert_eq!(body["recent_delivers"][0]["agent"], "worker-a"); assert_eq!(body["recent_delivers"][0]["seq"], 7); assert_eq!(body["recent_delivers"][0]["decision"], "deliver"); - assert_eq!(body["recent_delivers"][0]["disposition"], "injected"); + assert_eq!( + body["recent_delivers"][0]["disposition"], + "queued_for_injection" + ); // Nothing was asked of the runtime. assert!( diff --git a/crates/broker/src/node_delivery_probe.rs b/crates/broker/src/node_delivery_probe.rs index 89fd2a74cb..2e035081d1 100644 --- a/crates/broker/src/node_delivery_probe.rs +++ b/crates/broker/src/node_delivery_probe.rs @@ -82,12 +82,12 @@ fn now_ms() -> u64 { /// What `handle_fleet_deliver` ultimately did with a frame. Recorded separately /// from the [`DeliveryDecision`] because a decision of `Deliver` still has -/// several possible ends — injected, held for a manual flush, or failed at the +/// several possible ends — queued_for_injection, held for a manual flush, or failed at the /// PTY boundary — and "where did it stop" is the whole question this answers. #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub(crate) enum DeliverDisposition { - /// Crossed the PTY injection boundary; ack withheld pending worker echo. - Injected, + /// Accepted into pending injection; neither PTY write nor consumption confirmed. + QueuedForInjection, /// Surfaced with nothing to verify (ambient receipt/reaction); acked now. SurfacedAndAcked, /// Received into the volatile FIFO, owned by Relaycast until a flush. @@ -107,7 +107,7 @@ pub(crate) enum DeliverDisposition { impl DeliverDisposition { fn as_str(self) -> &'static str { match self { - Self::Injected => "injected", + Self::QueuedForInjection => "queued_for_injection", Self::SurfacedAndAcked => "surfaced_and_acked", Self::HeldForManualFlush => "held_for_manual_flush", Self::SurfaceFailed => "surface_failed", @@ -200,10 +200,10 @@ pub(crate) struct AgentCursorView { /// /// These rows persist per agent, so the diagnosis is a single read: /// `delivers_seen` not advancing for the agent means the frame never reached -/// this broker (look upstream); advancing while `injected` does not means the +/// this broker (look upstream); advancing while `queued_for_injection` does not means the /// delivery book discarded it, and the decision counts say which way. -/// `last_injected_at_ms` is the per-route last-confirmed-delivery asked for in -/// relay#1593 — it separates a deaf agent from a merely quiet one. +/// `last_queued_for_injection_at_ms` records the pending handoff only. Use worker +/// confirmation/ACK counters and recipient session evidence for actual delivery. #[derive(Debug, Default, Clone)] struct AgentStats { agent_id: String, @@ -213,7 +213,7 @@ struct AgentStats { decision_stale: u64, decision_gap: u64, decision_identity_reject: u64, - injected: u64, + queued_for_injection: u64, surfaced_and_acked: u64, held_for_manual_flush: u64, surface_failed: u64, @@ -221,7 +221,7 @@ struct AgentStats { rejected_identity: u64, rejected_sequence_gap: u64, last_deliver_at_ms: u64, - last_injected_at_ms: u64, + last_queued_for_injection_at_ms: u64, /// Strictly increasing rank of the last time this row was touched. See /// [`agent_row`] — eviction orders on this, not on the millisecond clock. last_touch_order: u64, @@ -241,7 +241,7 @@ impl AgentStats { "identity_reject": self.decision_identity_reject, }, "dispositions": { - "injected": self.injected, + "queued_for_injection": self.queued_for_injection, "surfaced_and_acked": self.surfaced_and_acked, "held_for_manual_flush": self.held_for_manual_flush, "surface_failed": self.surface_failed, @@ -250,7 +250,7 @@ impl AgentStats { "rejected_sequence_gap": self.rejected_sequence_gap, }, "last_deliver_at_ms": non_zero(self.last_deliver_at_ms), - "last_injected_at_ms": non_zero(self.last_injected_at_ms), + "last_queued_for_injection_at_ms": non_zero(self.last_queued_for_injection_at_ms), }) } } @@ -269,7 +269,7 @@ struct Counters { decision_stale: AtomicU64, decision_gap: AtomicU64, decision_identity_reject: AtomicU64, - injected: AtomicU64, + queued_for_injection: AtomicU64, surfaced_and_acked: AtomicU64, held_for_manual_flush: AtomicU64, surface_failed: AtomicU64, @@ -455,7 +455,7 @@ impl NodeDeliveryProbe { /// decision and outcome together rather than having to infer the join. pub(crate) fn record_disposition(&self, deliver: &Deliver, disposition: DeliverDisposition) { let counter = match disposition { - DeliverDisposition::Injected => &self.counters.injected, + DeliverDisposition::QueuedForInjection => &self.counters.queued_for_injection, DeliverDisposition::SurfacedAndAcked => &self.counters.surfaced_and_acked, DeliverDisposition::HeldForManualFlush => &self.counters.held_for_manual_flush, DeliverDisposition::SurfaceFailed => &self.counters.surface_failed, @@ -479,11 +479,10 @@ impl NodeDeliveryProbe { } if let Some(stats) = agent_row(&mut retained.agents, &bounded(&deliver.agent), touch) { match disposition { - DeliverDisposition::Injected => { - stats.injected += 1; - // The per-route "last confirmed delivery" relay#1593 asked - // for: it separates a deaf agent from a merely quiet one. - stats.last_injected_at_ms = now_ms(); + DeliverDisposition::QueuedForInjection => { + stats.queued_for_injection += 1; + // This is queue acceptance, not worker confirmation. + stats.last_queued_for_injection_at_ms = now_ms(); } DeliverDisposition::SurfacedAndAcked => stats.surfaced_and_acked += 1, DeliverDisposition::HeldForManualFlush => stats.held_for_manual_flush += 1, @@ -614,7 +613,7 @@ impl NodeDeliveryProbe { "identity_reject": load(&c.decision_identity_reject), }, "dispositions": { - "injected": load(&c.injected), + "queued_for_injection": load(&c.queued_for_injection), "surfaced_and_acked": load(&c.surfaced_and_acked), "held_for_manual_flush": load(&c.held_for_manual_flush), "surface_failed": load(&c.surface_failed), @@ -814,7 +813,7 @@ mod tests { let second = deliver("worker", "ag_1", "del_2", 2); probe.record_decision(&first, &DeliveryDecision::Deliver { up_to_seq: 1 }); probe.record_decision(&second, &DeliveryDecision::IdentityReject); - probe.record_disposition(&first, DeliverDisposition::Injected); + probe.record_disposition(&first, DeliverDisposition::QueuedForInjection); probe.record_disposition(&second, DeliverDisposition::RejectedIdentity); let snapshot = probe.snapshot_with_token(true); @@ -822,13 +821,13 @@ mod tests { assert_eq!(recent.len(), 2); assert_eq!(recent[0]["delivery_id"], "del_1"); assert_eq!(recent[0]["decision"], "deliver"); - assert_eq!(recent[0]["disposition"], "injected"); + assert_eq!(recent[0]["disposition"], "queued_for_injection"); assert_eq!(recent[1]["delivery_id"], "del_2"); assert_eq!(recent[1]["decision"], "identity_reject"); assert_eq!(recent[1]["disposition"], "rejected_identity"); assert_eq!(snapshot["decisions"]["deliver"], 1); assert_eq!(snapshot["decisions"]["identity_reject"], 1); - assert_eq!(snapshot["dispositions"]["injected"], 1); + assert_eq!(snapshot["dispositions"]["queued_for_injection"], 1); assert_eq!(snapshot["dispositions"]["rejected_identity"], 1); } @@ -949,10 +948,10 @@ mod tests { fn per_agent_rows_localize_a_single_deaf_agent() { let probe = NodeDeliveryProbe::new(); - // A healthy agent: frame arrives and is injected. + // A healthy agent: frame arrives and is queued_for_injection. let healthy = deliver("healthy-agent", "ag_ok", "del_ok", 1); probe.record_decision(&healthy, &DeliveryDecision::Deliver { up_to_seq: 1 }); - probe.record_disposition(&healthy, DeliverDisposition::Injected); + probe.record_disposition(&healthy, DeliverDisposition::QueuedForInjection); // A deaf agent: the frame reaches the broker but the delivery book // rejects it on identity, so it never enters the pending queue — @@ -972,17 +971,17 @@ mod tests { let healthy_row = row("healthy-agent"); assert_eq!(healthy_row["delivers_seen"], 1); - assert_eq!(healthy_row["dispositions"]["injected"], 1); - assert!(healthy_row["last_injected_at_ms"].is_u64()); + assert_eq!(healthy_row["dispositions"]["queued_for_injection"], 1); + assert!(healthy_row["last_queued_for_injection_at_ms"].is_u64()); let deaf_row = row("deaf-agent"); // The frame DID arrive — so this is not an upstream problem... assert_eq!(deaf_row["delivers_seen"], 1); assert_eq!(deaf_row["decisions"]["identity_reject"], 1); - // ...but it was never injected, and the per-route last-confirmed + // ...but it was never queued_for_injection, and the per-route last-confirmed // delivery relay#1593 asked for is null, separating deaf from quiet. - assert_eq!(deaf_row["dispositions"]["injected"], 0); - assert_eq!(deaf_row["last_injected_at_ms"], Value::Null); + assert_eq!(deaf_row["dispositions"]["queued_for_injection"], 0); + assert_eq!(deaf_row["last_queued_for_injection_at_ms"], Value::Null); assert!(deaf_row["last_deliver_at_ms"].is_u64()); } @@ -1015,7 +1014,7 @@ mod tests { assert_eq!(row["dispositions"]["rejected_identity"], 0); // Arrived, never delivered: the pair that localizes the failure. assert_eq!(row["delivers_seen"], 1); - assert_eq!(row["last_injected_at_ms"], Value::Null); + assert_eq!(row["last_queued_for_injection_at_ms"], Value::Null); } #[test] @@ -1086,7 +1085,7 @@ mod tests { frame.payload = json!({ "type": oversized }); probe.record_decision(&frame, &DeliveryDecision::Deliver { up_to_seq: 1 }); - probe.record_disposition(&frame, DeliverDisposition::Injected); + probe.record_disposition(&frame, DeliverDisposition::QueuedForInjection); probe.record_parse_failure("boom", &json!({ "type": oversized }).to_string()); let snapshot = probe.snapshot_with_token(true); @@ -1100,7 +1099,7 @@ mod tests { ); } assert_eq!( - row["disposition"], "injected", + row["disposition"], "queued_for_injection", "bounding the retained delivery_id must not break the join that \ stamps the disposition onto its frame" ); @@ -1112,7 +1111,7 @@ mod tests { agent.len() ); assert_eq!( - snapshot["agents"][0]["dispositions"]["injected"], 1, + snapshot["agents"][0]["dispositions"]["queued_for_injection"], 1, "bounding the agent name on both writers must keep them on one row" ); diff --git a/crates/broker/src/runtime/fleet.rs b/crates/broker/src/runtime/fleet.rs index a85f65e614..08389c607a 100644 --- a/crates/broker/src/runtime/fleet.rs +++ b/crates/broker/src/runtime/fleet.rs @@ -890,7 +890,7 @@ impl BrokerRuntime { // `insert_and_attempt_delivery`), so there is nothing left // to record here — see relay#1543. self.node_delivery_probe - .record_disposition(&deliver, DeliverDisposition::Injected); + .record_disposition(&deliver, DeliverDisposition::QueuedForInjection); self.fleet_delivery_book.commit_received(&deliver); return; } diff --git a/packages/harness-driver/src/protocol.ts b/packages/harness-driver/src/protocol.ts index 445ed3e77e..1e524c9c75 100644 --- a/packages/harness-driver/src/protocol.ts +++ b/packages/harness-driver/src/protocol.ts @@ -293,7 +293,7 @@ export interface BrokerStatus { /** Where a `deliver` frame ended up once the broker had acted on it. */ export type NodeDeliveryDisposition = - | 'injected' + | 'queued_for_injection' | 'surfaced_and_acked' | 'held_for_manual_flush' | 'surface_failed' @@ -319,7 +319,7 @@ export interface NodeDeliveryRecord { decision: 'deliver' | 'duplicate' | 'stale' | 'gap' | 'identity_reject'; /** Where the frame ended up. `null` while still in flight. */ disposition: - | 'injected' + | 'queued_for_injection' | 'surfaced_and_acked' | 'held_for_manual_flush' | 'surface_failed' @@ -334,7 +334,7 @@ export interface NodeDeliveryRecord { * `recent_delivers` so a single deaf agent stays diagnosable on a busy broker. * * `delivers_seen` not advancing means the frame never reached this broker; - * advancing while `dispositions.injected` does not means the delivery book + * advancing while `dispositions.queued_for_injection` does not means the delivery book * discarded it, and `decisions` says which way. */ export interface NodeDeliveryAgentRow { @@ -345,7 +345,7 @@ export interface NodeDeliveryAgentRow { dispositions: Record; last_deliver_at_ms: number | null; /** Last confirmed delivery to this agent — a deaf agent from a quiet one. */ - last_injected_at_ms: number | null; + last_queued_for_injection_at_ms: number | null; } /** diff --git a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs index f1c6b3dcca..98d0e69bbc 100644 --- a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs +++ b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs @@ -50,7 +50,7 @@ const ENGINE_READY_TIMEOUT_MS = 60_000; */ const DECISIONS = ['deliver', 'duplicate', 'stale', 'gap', 'identity_reject']; const DISPOSITIONS = [ - 'injected', + 'queued_for_injection', 'surfaced_and_acked', 'held_for_manual_flush', 'surface_failed', From c0950f59fe85483d24a4d13772099badb98f23f9 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:58:09 +0200 Subject: [PATCH 04/13] fix(broker): validate diagnostic privacy and unreleased notes Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- CHANGELOG.md | 10 +++++----- crates/broker/src/node_delivery_probe.rs | 10 ++++++---- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0215839418..57b6ce3e2f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,7 +5,11 @@ All notable changes to Agent Relay will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). -## [Unreleased] +## [Unreleased - Minor] + +### Added + +- Broker `GET /api/node-delivery` exposes frame arrival, routing decisions, pending handoff, and acknowledgement counters without requiring logs or a restart. ## [12.1.0] - 2026-09-12 @@ -90,10 +94,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [11.10.4] - 2026-09-08 -### Added - -- Broker `GET /api/node-delivery` reports whether node-control `deliver` frames are reaching an agent, what the delivery book decided about each one, where it ended up, and whether the resulting `delivery_ack` actually left the broker, so a deaf agent can be told from a quiet one without restarting the broker. - ### Changed - `agent-relay fleet spawn --sandbox` now requests Cloud's long-running workload profile and reports the provider Cloud actually selected, enabling Agent37 placement without a provider flag. diff --git a/crates/broker/src/node_delivery_probe.rs b/crates/broker/src/node_delivery_probe.rs index 2e035081d1..6d49d80bac 100644 --- a/crates/broker/src/node_delivery_probe.rs +++ b/crates/broker/src/node_delivery_probe.rs @@ -903,8 +903,7 @@ mod tests { let recorded = snapshot["last_parse_failure"]["error"] .as_str() .expect("the failure must still be recorded"); - // Truncated on a boundary, and still bounded in BYTES — taking N chars - // instead would admit up to 4x the limit. + // Peer error strings are replaced with a fixed local category. assert!(recorded.len() <= ERROR_EXCERPT_LIMIT); assert_eq!(recorded, "invalid node-control frame"); assert!(!recorded.contains("é")); @@ -915,6 +914,10 @@ mod tests { fn parse_failure_does_not_echo_invalid_peer_values_from_serde() { let raw = r#"{"type":"deliver","v":1,"seq":"PRIVATE_BODY_IN_INVALID_VALUE"}"#; let error = serde_json::from_str::(raw).unwrap_err(); + assert!( + error.to_string().contains("PRIVATE_BODY_IN_INVALID_VALUE"), + "test must exercise a serde error that echoes a peer value" + ); let probe = NodeDeliveryProbe::new(); probe.record_parse_failure(&error.to_string(), raw); let report = probe.snapshot_with_token(true).to_string(); @@ -978,8 +981,7 @@ mod tests { // The frame DID arrive — so this is not an upstream problem... assert_eq!(deaf_row["delivers_seen"], 1); assert_eq!(deaf_row["decisions"]["identity_reject"], 1); - // ...but it was never queued_for_injection, and the per-route last-confirmed - // delivery relay#1593 asked for is null, separating deaf from quiet. + // ...but it was never accepted into the pending injection path. assert_eq!(deaf_row["dispositions"]["queued_for_injection"], 0); assert_eq!(deaf_row["last_queued_for_injection_at_ms"], Value::Null); assert!(deaf_row["last_deliver_at_ms"].is_u64()); From eba2abe89a283b79bdb23c5a1343a5d6ed9335ad Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:58:52 +0200 Subject: [PATCH 05/13] test(broker): probe delivery using provider-owned node action spawns Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- .../1678-node-delivery-introspection/run.mjs | 38 +++++++++++++++---- tests/relayflows/shared/relaycast-engine.mjs | 2 +- 2 files changed, 32 insertions(+), 8 deletions(-) diff --git a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs index 98d0e69bbc..5538cd0f75 100644 --- a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs +++ b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs @@ -136,7 +136,17 @@ try { broker = spawn( binaryPath, - ['init', '--api-port', '0', '--api-bind', '127.0.0.1', '--state-dir', stateDir], + [ + 'init', + '--instance-name', + 'relayflow-1678-node', + '--api-port', + '0', + '--api-bind', + '127.0.0.1', + '--state-dir', + stateDir, + ], { cwd: workDir, env: { @@ -151,6 +161,7 @@ try { RELAY_NODE_ID: nodeId, RELAY_BROKER_API_KEY: BROKER_API_KEY, RELAY_SKIP_TELEMETRY: '1', + AGENT_RELAY_NODE_HARNESSES: 'cat', // RUST_LOG is deliberately absent — see the file header. }, stdio: ['ignore', 'pipe', 'pipe'], @@ -186,7 +197,25 @@ try { await waitFor(() => api('GET', '/api/status').then(() => true), 'the broker API to answer'); // A live worker, registered with the real engine and idle. - await api('POST', '/api/spawn', { name: AGENT, cli: 'cat', transport: 'pty' }); + const sender = await eng('POST', '/v1/agents', { name: 'proof-sender', type: 'agent' }, wsAuth); + const senderToken = sender.body?.data?.token; + if (!senderToken) throw new Error('Local proof sender registration failed.'); + // Node action spawn creates the recipient on the broker provider. HTTP + // create+bind defaults to another provider and cannot prove this path. + await eng( + 'POST', + '/v1/actions/spawn/invoke', + { + input: { + name: AGENT, + cli: 'cat', + capability: 'spawn:cat', + node: 'relayflow-1678-node', + target_node: 'relayflow-1678-node', + }, + }, + { authorization: `Bearer ${senderToken}` } + ); await waitFor(async () => { const row = await eng('GET', '/v1/agents', undefined, wsAuth); const list = row.body?.data?.agents ?? row.body?.data ?? []; @@ -241,11 +270,6 @@ try { ); } - const sender = await eng('POST', '/v1/agents', { name: 'proof-sender', type: 'agent' }, wsAuth); - const senderToken = sender.body?.data?.token; - if (!senderToken) { - throw new Error(`sender create failed: ${JSON.stringify(sender.body).slice(0, 300)}`); - } await eng( 'POST', '/v1/dm', diff --git a/tests/relayflows/shared/relaycast-engine.mjs b/tests/relayflows/shared/relaycast-engine.mjs index 8469425bb3..3fd489577d 100644 --- a/tests/relayflows/shared/relaycast-engine.mjs +++ b/tests/relayflows/shared/relaycast-engine.mjs @@ -23,7 +23,7 @@ import path from 'node:path'; import { promisify } from 'node:util'; const execFile = promisify(execFileCb); -export const ENGINE_VERSION = '8.2.2'; +export const ENGINE_VERSION = '8.10.1'; const SERVE_BIN = 'node_modules/@relaycast/engine/dist/bin/serve.js'; /** From 9c8c5bad4c487ea6144d8c72d7d8d2932cfe7d84 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:01:22 +0200 Subject: [PATCH 06/13] test(broker): wait for node control before diagnostic spawn Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- .../cases/1678-node-delivery-introspection/run.mjs | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs index 5538cd0f75..b7bd45656e 100644 --- a/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs +++ b/tests/relayflows/cases/1678-node-delivery-introspection/run.mjs @@ -194,7 +194,10 @@ try { return `http://127.0.0.1:${port}`; }, 'the broker connection file to publish its bound API port'); const api = brokerClient(brokerUrl); - await waitFor(() => api('GET', '/api/status').then(() => true), 'the broker API to answer'); + await waitFor( + async () => (await api('GET', '/api/status')).node_connected === true, + 'the node control connection to establish' + ); // A live worker, registered with the real engine and idle. const sender = await eng('POST', '/v1/agents', { name: 'proof-sender', type: 'agent' }, wsAuth); @@ -202,7 +205,7 @@ try { if (!senderToken) throw new Error('Local proof sender registration failed.'); // Node action spawn creates the recipient on the broker provider. HTTP // create+bind defaults to another provider and cannot prove this path. - await eng( + const spawned = await eng( 'POST', '/v1/actions/spawn/invoke', { @@ -216,6 +219,7 @@ try { }, { authorization: `Bearer ${senderToken}` } ); + if (spawned.status < 200 || spawned.status >= 300) throw new Error('Local node action spawn was rejected.'); await waitFor(async () => { const row = await eng('GET', '/v1/agents', undefined, wsAuth); const list = row.body?.data?.agents ?? row.body?.data ?? []; From 5153e866802f6cd4ee6ac631d18510d836f73cc6 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 04:59:22 +0200 Subject: [PATCH 07/13] fix(broker): gate node delivery on accepted provider registration Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- CHANGELOG.md | 4 + crates/broker/src/node_control.rs | 114 ++++++-- .../src/node_control/registration_tests.rs | 249 ++++++++++++++++++ .../1593-node-registration-gate/case.json | 13 + .../cases/1593-node-registration-gate/run.mjs | 96 +++++++ 5 files changed, 459 insertions(+), 17 deletions(-) create mode 100644 crates/broker/src/node_control/registration_tests.rs create mode 100644 tests/relayflows/cases/1593-node-registration-gate/case.json create mode 100644 tests/relayflows/cases/1593-node-registration-gate/run.mjs diff --git a/CHANGELOG.md b/CHANGELOG.md index 57b6ce3e2f..2a533e65ba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Broker `GET /api/node-delivery` exposes frame arrival, routing decisions, pending handoff, and acknowledgement counters without requiring logs or a restart. +### Fixed + +- Broker node connections now require an accepted registration before reporting readiness or publishing inventory and heartbeats; rejected and unanswered registrations reconnect with bounded backoff. + ## [12.1.0] - 2026-09-12 ### Added diff --git a/crates/broker/src/node_control.rs b/crates/broker/src/node_control.rs index 2ae45d3d3d..c5663bbfb0 100644 --- a/crates/broker/src/node_control.rs +++ b/crates/broker/src/node_control.rs @@ -1909,6 +1909,72 @@ impl Drop for ProbeSessionGuard<'_> { } } +/// An authenticated socket is not yet the authoritative broker provider. The +/// engine can reject node.register while leaving the socket open; sending +/// inventory or heartbeats then updates a fallback provider and masks the loss. +/// Only this request's successful reply opens the application delivery path. +async fn register_node_session( + sink: &mut S, + stream: &mut R, + registration: &mut NodeRegister, + config: &FleetControlConfig, +) -> bool +where + S: Sink + Unpin, + S::Error: std::error::Error + Send + Sync + 'static, + R: futures_util::Stream> + Unpin, +{ + let id = format!("node_register_{}", Uuid::new_v4().simple()); + registration.id = Some(id.clone()); + // Bound both the write and the response, including peers which keep sending + // pongs or unrelated replies. Tests may use their shorter transport budget. + let deadline = config + .read_idle_timeout + .unwrap_or(Duration::from_secs(10)) + .min(Duration::from_secs(10)); + let accepted = tokio::time::timeout(deadline, async { + if send_wire(sink, &BrokerToRelaycast::NodeRegister(registration.clone())).await.is_err() { + return false; + } + while let Some(Ok(message)) = stream.next().await { + match message { + Message::Text(text) => { + if let Some(probe) = config.probe.as_ref() { probe.record_text_frame(); } + match serde_json::from_str::(&text) { + Ok(frame) => { + if let Some(probe) = config.probe.as_ref() { probe.record_frame(&frame); } + match frame { + RelaycastToBroker::Reply(reply) if reply.id == id => return reply.ok, + RelaycastToBroker::Error(error) => { + tracing::error!(code = %error.code, "node registration rejected; reconnecting without advertising delivery readiness"); + return false; + } + // The engine replies before replaying deliveries. Never + // acknowledge or inject a frame on an unaccepted provider. + RelaycastToBroker::Deliver(_) | RelaycastToBroker::ActionInvoke(_) => return false, + _ => {}, + } + } + Err(error) => { + if let Some(probe) = config.probe.as_ref() { probe.record_parse_failure(&error.to_string(), &text); } + } + } + } + Message::Ping(payload) => { + if sink.send(Message::Pong(payload)).await.is_err() { return false; } + } + Message::Close(_) => return false, + _ => {}, + } + } + false + }).await.unwrap_or(false); + if !accepted { + tracing::warn!("node registration was not accepted within its deadline; delivery unavailable, reconnecting"); + } + accepted +} + async fn run_connected_once( config: &FleetControlConfig, command_rx: &mut mpsc::Receiver, @@ -1981,21 +2047,16 @@ async fn run_connected_once( }; // Socket-owned connectivity: armed here, released by Drop on every exit. let _probe_session = ProbeSessionGuard::enter(config.probe.as_ref()); - let _ = event_tx.send(FleetControlEvent::Connected).await; let (mut sink, mut stream) = ws.split(); let mut pending_agent_registrations: HashMap = HashMap::new(); let mut pending_deregistrations: HashMap>> = HashMap::new(); - if send_wire( - &mut sink, - &BrokerToRelaycast::NodeRegister(node_register.clone()), - ) - .await - .is_err() - { + if !register_node_session(&mut sink, &mut stream, &mut node_register, config).await { return ControlRunResult::Disconnected; } + *registration = Some(node_register.clone()); + let _ = event_tx.send(FleetControlEvent::Connected).await; if !send_inventory_sync(&mut sink, inventory, &mut pending_agent_registrations).await { return ControlRunResult::Disconnected; } @@ -2032,11 +2093,15 @@ async fn run_connected_once( load.handlers_live = true; let mut next = build_node_register(&manifest, &config.node_id, &config.node_name, &config.broker_version, resume_cursor); next.provider = Some(provider.clone()); - node_register = next.clone(); - *registration = Some(next.clone()); - if send_wire(&mut sink, &BrokerToRelaycast::NodeRegister(next)).await.is_err() { - return ControlRunResult::Disconnected; + // Reopen the provider session for a new manifest. Running + // the registration gate inside this active socket would + // consume replies belonging to in-flight agent requests. + *registration = Some(next); + drain_agent_registrations(&mut pending_agent_registrations, "node_control_reconfiguring"); + for (_, pending) in pending_deregistrations.drain() { + let _ = pending.send(Err("node_control_reconfiguring".to_string())); } + return ControlRunResult::Disconnected; } Some(FleetControlCommand::UpdateInventory(next)) => { *inventory = next; @@ -4241,6 +4306,7 @@ mod tests { let server = tokio::spawn(async move { let (stream, _) = listener.accept().await.unwrap(); let mut ws = accept_async(stream).await.unwrap(); + let _ = next_node_to_server(&mut ws).await; while ws.next().await.is_some() {} }); @@ -4609,7 +4675,7 @@ mod tests { ); let driver = async { // Both frames counted -> the client has drained the read side. - wait_for_probe(&probe, |snapshot| snapshot["socket"]["text_frames"] == 2).await; + wait_for_probe(&probe, |snapshot| snapshot["socket"]["text_frames"] == 3).await; command_tx .send(FleetControlCommand::Shutdown) .await @@ -4624,10 +4690,10 @@ mod tests { server.abort(); let snapshot = probe.snapshot_with_token(true); - // BOTH frames are counted as arrived, including the one that could not - // be parsed. If the count moved after the parse, this would read 1. + // Registration reply plus BOTH test frames count as arrived, including + // the unparseable one. Counting after parse would incorrectly read 2. assert_eq!( - snapshot["socket"]["text_frames"], 2, + snapshot["socket"]["text_frames"], 3, "an unparseable frame must still count as having arrived: {snapshot}" ); assert_eq!(snapshot["socket"]["parse_failures"], 1); @@ -5079,11 +5145,21 @@ mod tests { async fn next_node_to_server(ws: &mut S) -> BrokerToRelaycast where S: futures_util::Stream> + + Sink + Unpin, { loop { if let Message::Text(text) = ws.next().await.unwrap().unwrap() { - return serde_json::from_str(&text).unwrap(); + let frame = serde_json::from_str(&text).unwrap(); + if let BrokerToRelaycast::NodeRegister(register) = &frame { + ws.send(Message::Text( + json!({"v":1,"type":"reply","id":register.id,"ok":true,"data":{}}) + .to_string(), + )) + .await + .unwrap(); + } + return frame; } } } @@ -5091,6 +5167,7 @@ mod tests { async fn next_non_heartbeat_node_to_server(ws: &mut S) -> BrokerToRelaycast where S: futures_util::Stream> + + Sink + Unpin, { loop { @@ -5336,3 +5413,6 @@ mod tests { )); } } + +#[cfg(test)] +mod registration_tests; diff --git a/crates/broker/src/node_control/registration_tests.rs b/crates/broker/src/node_control/registration_tests.rs new file mode 100644 index 0000000000..415471a113 --- /dev/null +++ b/crates/broker/src/node_control/registration_tests.rs @@ -0,0 +1,249 @@ +//! Real loopback WS regression for an authenticated but unregistered provider. +use super::*; +use serde_json::{json, Value}; +use tokio::net::TcpListener; +use tokio_tungstenite::accept_async; + +async fn registration_gate_case(response: &str) { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let ws_url = format!("ws://{}/v1/node/ws", listener.local_addr().unwrap()); + let (command_tx, mut command_rx) = mpsc::channel(8); + let (event_tx, mut event_rx) = mpsc::channel(8); + let mut registration = Some(NodeRegister { + v: FLEET_WIRE_VERSION, + id: None, + name: "test-node".into(), + node_id: "node-test".into(), + provider: None, + capabilities: vec![], + max_agents: 8, + tags: vec![], + repo_keys: None, + version: "test".into(), + machine_id: None, + resume_cursor: None, + }); + let mut inventory = vec![InventoryAgent { + name: "old-worker".into(), + agent_id: "old-worker-id".into(), + invocation_id: None, + session_ref: Some("old-session".into()), + }]; + let mut load = FleetLoadSnapshot { + active_agents: 1, + max_agents: 8, + handlers_live: true, + active_agent_names: vec!["old-worker".into()], + }; + let accepted = response == "accept" || response == "reconfigure"; + let reconfigure = response == "reconfigure"; + let server_command_tx = command_tx.clone(); + let response = response.to_owned(); + let server = tokio::spawn(async move { + let (tcp, _) = listener.accept().await.unwrap(); + let mut ws = accept_async(tcp).await.unwrap(); + let Message::Text(raw) = ws.next().await.unwrap().unwrap() else { + panic!("node.register expected") + }; + let frame: Value = serde_json::from_str(&raw).unwrap(); + assert_eq!(frame["type"], "node.register"); + let id = frame["id"].as_str().unwrap_or("uncorrelated-base-request"); + if accepted { + // Keep the socket live without accepting the provider. Neither an + // unrelated success nor transport traffic may open the gate. + ws.send(Message::Text( + json!({"v":1,"type":"reply","ok":true,"id":"unrelated","data":{}}).to_string(), + )) + .await + .unwrap(); + assert!(tokio::time::timeout(Duration::from_millis(30), ws.next()) + .await + .is_err()); + ws.send(Message::Text( + json!({"v":1,"type":"reply","ok":true,"id":id,"data":{}}).to_string(), + )) + .await + .unwrap(); + for expected in ["inventory.sync", "node.heartbeat"] { + let Message::Text(raw) = ws.next().await.unwrap().unwrap() else { + panic!("text frame expected"); + }; + assert_eq!( + serde_json::from_str::(&raw).unwrap()["type"], + expected + ); + } + if reconfigure { + let (register_reply, register_result) = oneshot::channel(); + let (deregister_reply, deregister_result) = oneshot::channel(); + server_command_tx + .send(FleetControlCommand::RegisterAgent { + request: serde_json::from_value(json!({"v":1,"name":"pending-worker"})) + .unwrap(), + reply: register_reply, + }) + .await + .unwrap(); + server_command_tx + .send(FleetControlCommand::DeregisterAgent { + request: serde_json::from_value( + json!({"v":1,"agent_id":"retiring-worker-id","name":"retiring-worker"}), + ) + .unwrap(), + reply: deregister_reply, + }) + .await + .unwrap(); + for expected in ["agent.register", "agent.deregister"] { + loop { + let Message::Text(raw) = ws.next().await.unwrap().unwrap() else { + continue; + }; + let frame: Value = serde_json::from_str(&raw).unwrap(); + if frame["type"] == "node.heartbeat" { + continue; + } + assert_eq!(frame["type"], expected); + break; + } + } + server_command_tx + .send(FleetControlCommand::RegisterNode { + manifest: NodeManifest { + name: "updated-node".into(), + node_id: None, + capabilities: vec![], + max_agents: None, + tags: None, + repo_keys: None, + version: None, + }, + resume_cursor: None, + }) + .await + .unwrap(); + assert_eq!( + register_result.await.unwrap().unwrap_err(), + "node_control_reconfiguring" + ); + assert_eq!( + deregister_result.await.unwrap().unwrap_err(), + "node_control_reconfiguring" + ); + return; + } + for name in ["old-worker", "fresh-worker"] { + ws.send(Message::Text(json!({"v":1,"type":"deliver","agent":name,"agent_id":format!("{name}-id"),"delivery_id":format!("delivery-{name}"),"msg_id":format!("message-{name}"),"seq":1,"mode":"wait","payload":{"type":"dm.received","text":"local probe"}}).to_string())).await.unwrap(); + } + ws.close(None).await.unwrap(); + return; + } + if response != "timeout" { + let reply = match response.as_str() { + "error" => { + json!({"v":1,"type":"error","ok":false,"id":id,"code":"provider_instance_conflict","message":"incumbent provider still live"}) + } + "false" => json!({"v":1,"type":"reply","ok":false,"id":id,"data":{}}), + "uncorrelated" => { + json!({"v":1,"type":"reply","ok":true,"id":"some-other-request","data":{}}) + } + _ => panic!("unknown arm"), + }; + ws.send(Message::Text(reply.to_string())).await.unwrap(); + } + // A failed registration must never be followed by inventory, heartbeat, + // agent registration or an ACK on the unauthoritative socket. + while let Ok(Some(Ok(frame))) = + tokio::time::timeout(Duration::from_secs(1), ws.next()).await + { + match frame { + Message::Text(raw) => panic!( + "registration-dependent frame escaped gate: {}", + serde_json::from_str::(&raw).unwrap()["type"] + ), + Message::Close(_) => break, + _ => {} + } + } + }); + let result = tokio::time::timeout( + Duration::from_secs(2), + run_connected_once( + &FleetControlConfig { + ws_url, + node_token: Some("nt_test".into()), + node_id: "node-test".into(), + node_name: "test-node".into(), + broker_version: "test".into(), + token_minter: None, + session_token: None, + read_idle_timeout: Some(Duration::from_millis(150)), + probe: None, + }, + &mut command_rx, + &event_tx, + &mut registration, + &mut inventory, + &mut load, + Duration::from_millis(50), + ), + ) + .await + .expect("registration rejection/timeout must terminate the session"); + assert_eq!(result, ControlRunResult::Disconnected); + if accepted { + assert!(matches!( + event_rx.try_recv(), + Ok(FleetControlEvent::Connected) + )); + for expected in if reconfigure { + vec![] + } else { + vec!["old-worker", "fresh-worker"] + } { + let Ok(FleetControlEvent::Message(RelaycastToBroker::Deliver(deliver))) = + event_rx.try_recv() + else { + panic!("accepted provider must forward the paired deliveries") + }; + assert_eq!(deliver.agent, expected); + assert_eq!(deliver.msg_id, format!("message-{expected}")); + } + assert!(event_rx.try_recv().is_err(), "no duplicate deliveries"); + } else { + assert!( + !matches!(event_rx.try_recv(), Ok(FleetControlEvent::Connected)), + "transport acceptance must not report an unregistered provider connected" + ); + } + server + .await + .expect("the rejected socket emitted no dependent frames"); +} + +#[tokio::test] +async fn rejected_registration_never_advertises_or_syncs() { + registration_gate_case("error").await; +} +#[tokio::test] +async fn unsuccessful_registration_reply_never_advertises_or_syncs() { + registration_gate_case("false").await; +} +#[tokio::test] +async fn silent_registration_never_advertises_or_syncs() { + registration_gate_case("timeout").await; +} +#[tokio::test] +async fn unrelated_reply_cannot_open_registration_gate() { + registration_gate_case("uncorrelated").await; +} + +#[tokio::test] +async fn accepted_registration_forwards_paired_deliveries_once() { + registration_gate_case("accept").await; +} + +#[tokio::test] +async fn manifest_change_fails_pending_requests_before_reconnect() { + registration_gate_case("reconfigure").await; +} diff --git a/tests/relayflows/cases/1593-node-registration-gate/case.json b/tests/relayflows/cases/1593-node-registration-gate/case.json new file mode 100644 index 0000000000..38a62e80a7 --- /dev/null +++ b/tests/relayflows/cases/1593-node-registration-gate/case.json @@ -0,0 +1,13 @@ +{ + "version": 1, + "id": "1593-node-registration-gate", + "kind": "bugfix", + "title": "Reject an unauthoritative node session before inventory or readiness", + "runner": { "command": ["node", "tests/relayflows/cases/1593-node-registration-gate/run.mjs"] }, + "requirements": ["broker-linux-x64"], + "timeoutSeconds": 900, + "expected": { + "base": { "outcome": "bug", "signature": "rejected_registration_still_publishes_inventory" }, + "head": { "outcome": "fixed", "signature": "rejected_registration_never_opens_delivery_path" } + } +} diff --git a/tests/relayflows/cases/1593-node-registration-gate/run.mjs b/tests/relayflows/cases/1593-node-registration-gate/run.mjs new file mode 100644 index 0000000000..db0370107a --- /dev/null +++ b/tests/relayflows/cases/1593-node-registration-gate/run.mjs @@ -0,0 +1,96 @@ +// Execute the same real-loopback socket regression against each exact source +// revision. The production run_connected_once function is unchanged by the +// harness; only a cfg(test) module is installed in an isolated checkout. +import assert from 'node:assert/strict'; +import { execFileSync, spawnSync } from 'node:child_process'; +import { mkdtemp, mkdir, readFile, writeFile, rm } from 'node:fs/promises'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +const required = (name) => { + const v = process.env[name]; + if (!v) throw Error(`Missing ${name}`); + return v; +}; +const target = required('RELAY_PR_PROOF_TARGET_DIR'); +const harness = required('RELAY_PR_PROOF_HARNESS_DIR'); +const resultPath = required('RELAY_PR_PROOF_RESULT_PATH'); +const arm = required('RELAY_PR_PROOF_ARM'); +assert.ok(['base', 'head'].includes(arm)); +const sha = required(arm === 'base' ? 'RELAY_PR_PROOF_BASE_SHA' : 'RELAY_PR_PROOF_HEAD_SHA'); +assert.equal(execFileSync('git', ['-C', target, 'rev-parse', 'HEAD'], { encoding: 'utf8' }).trim(), sha); +const relative = path.relative(harness, fileURLToPath(import.meta.url)); +assert.ok(relative && !relative.startsWith('..') && !path.isAbsolute(relative)); +const temp = await mkdtemp(path.join(path.dirname(target), '.registration-proof-')); +const checkout = path.join(temp, 'target'); +let added = false; +try { + execFileSync('git', ['-C', target, 'worktree', 'add', '--detach', checkout, sha], { stdio: 'pipe' }); + added = true; + const sourcePath = path.join(checkout, 'crates/broker/src/node_control.rs'); + let source = await readFile(sourcePath, 'utf8'); + let test = await readFile( + path.join(harness, 'crates/broker/src/node_control/registration_tests.rs'), + 'utf8' + ); + // Older source revisions have no optional instrumentation handle. + if (!source.includes('pub(crate) probe:')) test = test.replace(/^\s*probe: None,\n/gm, '\n'); + if (!source.includes('mod registration_tests;')) source += '\n#[cfg(test)]\nmod registration_tests;\n'; + await writeFile(sourcePath, source); + await mkdir(path.join(checkout, 'crates/broker/src/node_control'), { recursive: true }); + await writeFile(path.join(checkout, 'crates/broker/src/node_control/registration_tests.rs'), test); + const env = { + ...process.env, + CARGO_TARGET_DIR: process.env.CARGO_TARGET_DIR ?? path.join(target, 'target'), + }; + for (const key of Object.keys(env)) + if (key.startsWith('GIT_CONFIG_') || key.startsWith('RELAY_ATTEST_')) delete env[key]; + const run = spawnSync( + 'cargo', + [ + 'test', + '-p', + 'agent-relay-broker', + '--lib', + 'node_control::registration_tests::rejected_registration_never_advertises_or_syncs', + '--', + '--exact', + ], + { cwd: checkout, env, encoding: 'utf8', timeout: 840000, maxBuffer: 8 * 1024 * 1024 } + ); + const output = (run.stdout ?? '') + (run.stderr ?? ''); + await mkdir(path.dirname(resultPath), { recursive: true }); + await writeFile(resultPath + '.log', output); + if (run.error) throw run.error; + let outcome, signature; + if (run.status === 0 && /1 passed; 0 failed/.test(output)) { + outcome = 'fixed'; + signature = 'rejected_registration_never_opens_delivery_path'; + } else if ( + run.status === 101 && + /registration-dependent frame escaped gate: "inventory.sync"/.test(output) && + /0 passed; 1 failed/.test(output) + ) { + outcome = 'bug'; + signature = 'rejected_registration_still_publishes_inventory'; + } else + throw Error( + `The socket regression did not reach a recognized outcome (exit ${run.status}); inspect its transcript.` + ); + await writeFile( + resultPath, + JSON.stringify({ + version: 1, + caseId: '1593-node-registration-gate', + arm, + outcome, + signature, + details: + 'A real loopback WebSocket peer rejects node.register while keeping transport open. The exact target production node-control loop must disconnect without advertising Connected or sending inventory.sync; compilation and unrelated failures are not evidence.', + }) + '\n' + ); + console.log(signature); +} finally { + if (added) + execFileSync('git', ['-C', target, 'worktree', 'remove', '--force', checkout], { stdio: 'pipe' }); + await rm(temp, { recursive: true, force: true }); +} From 5d51cd2dc0205bb5bbfbec35bb8e2fbdd53789ea Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:03:55 +0200 Subject: [PATCH 08/13] test(broker): verify registration gating with exact broker artifacts Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- .../cases/1593-node-registration-gate/run.mjs | 296 ++++++++++++++---- 1 file changed, 235 insertions(+), 61 deletions(-) diff --git a/tests/relayflows/cases/1593-node-registration-gate/run.mjs b/tests/relayflows/cases/1593-node-registration-gate/run.mjs index db0370107a..82f0427a93 100644 --- a/tests/relayflows/cases/1593-node-registration-gate/run.mjs +++ b/tests/relayflows/cases/1593-node-registration-gate/run.mjs @@ -1,9 +1,12 @@ -// Execute the same real-loopback socket regression against each exact source -// revision. The production run_connected_once function is unchanged by the -// harness; only a cfg(test) module is installed in an isolated checkout. +// Reuses the dependency-free HTTP/RFC6455 stand-in from relay#1636. +// Exercise the exact provided broker artifact; no source compilation or edits. import assert from 'node:assert/strict'; -import { execFileSync, spawnSync } from 'node:child_process'; -import { mkdtemp, mkdir, readFile, writeFile, rm } from 'node:fs/promises'; +import crypto from 'node:crypto'; +import http from 'node:http'; +import { execFileSync, spawn } from 'node:child_process'; +import { mkdtemp, mkdir, writeFile, rm, access } from 'node:fs/promises'; +import { constants } from 'node:fs'; +import { tmpdir } from 'node:os'; import path from 'node:path'; import { fileURLToPath } from 'node:url'; const required = (name) => { @@ -13,69 +16,231 @@ const required = (name) => { }; const target = required('RELAY_PR_PROOF_TARGET_DIR'); const harness = required('RELAY_PR_PROOF_HARNESS_DIR'); +const binary = required('RELAY_PR_PROOF_BROKER_BINARY'); const resultPath = required('RELAY_PR_PROOF_RESULT_PATH'); const arm = required('RELAY_PR_PROOF_ARM'); assert.ok(['base', 'head'].includes(arm)); -const sha = required(arm === 'base' ? 'RELAY_PR_PROOF_BASE_SHA' : 'RELAY_PR_PROOF_HEAD_SHA'); -assert.equal(execFileSync('git', ['-C', target, 'rev-parse', 'HEAD'], { encoding: 'utf8' }).trim(), sha); +const gitSha = (dir) => execFileSync('git', ['-C', dir, 'rev-parse', 'HEAD'], { encoding: 'utf8' }).trim(); +assert.equal( + gitSha(target), + required(arm === 'base' ? 'RELAY_PR_PROOF_BASE_SHA' : 'RELAY_PR_PROOF_HEAD_SHA') +); +assert.equal(gitSha(harness), required('RELAY_PR_PROOF_HEAD_SHA')); const relative = path.relative(harness, fileURLToPath(import.meta.url)); assert.ok(relative && !relative.startsWith('..') && !path.isAbsolute(relative)); -const temp = await mkdtemp(path.join(path.dirname(target), '.registration-proof-')); -const checkout = path.join(temp, 'target'); -let added = false; -try { - execFileSync('git', ['-C', target, 'worktree', 'add', '--detach', checkout, sha], { stdio: 'pipe' }); - added = true; - const sourcePath = path.join(checkout, 'crates/broker/src/node_control.rs'); - let source = await readFile(sourcePath, 'utf8'); - let test = await readFile( - path.join(harness, 'crates/broker/src/node_control/registration_tests.rs'), - 'utf8' +await access(binary, constants.R_OK | constants.X_OK); +const root = await mkdtemp(path.join(tmpdir(), 'relayflow-registration-')); +const state = path.join(root, 'state'); +await mkdir(state); +const sockets = new Set(); +const sessions = []; +let broker; +const WS_GUID = '258EAFA5-E914-47DA-95CA-C5AB0DC85B11'; +function encodeTextFrame(text) { + const payload = Buffer.from(text, 'utf8'); + const length = payload.length; + let header; + if (length < 126) { + header = Buffer.from([0x81, length]); + } else if (length < 65536) { + header = Buffer.alloc(4); + header[0] = 0x81; + header[1] = 126; + header.writeUInt16BE(length, 2); + } else { + header = Buffer.alloc(10); + header[0] = 0x81; + header[1] = 127; + header.writeBigUInt64BE(BigInt(length), 2); + } + return Buffer.concat([header, payload]); +} + +function createFrameReader(onText) { + let buffer = Buffer.alloc(0); + return (chunk) => { + buffer = Buffer.concat([buffer, chunk]); + for (;;) { + if (buffer.length < 2) return; + const opcode = buffer[0] & 0x0f; + const masked = (buffer[1] & 0x80) !== 0; + let length = buffer[1] & 0x7f; + let offset = 2; + if (length === 126) { + if (buffer.length < offset + 2) return; + length = buffer.readUInt16BE(offset); + offset += 2; + } else if (length === 127) { + if (buffer.length < offset + 8) return; + length = Number(buffer.readBigUInt64BE(offset)); + offset += 8; + } + let mask = null; + if (masked) { + if (buffer.length < offset + 4) return; + mask = buffer.subarray(offset, offset + 4); + offset += 4; + } + if (buffer.length < offset + length) return; + const payload = Buffer.from(buffer.subarray(offset, offset + length)); + buffer = buffer.subarray(offset + length); + if (mask) for (let i = 0; i < payload.length; i += 1) payload[i] ^= mask[i % 4]; + if (opcode === 0x1) onText(payload.toString('utf8')); + } + }; +} + +const server = http.createServer((request, response) => { + let body = ''; + request.on('data', (chunk) => { + body += chunk; + }); + request.on('end', () => { + const url = request.url.split('?')[0]; + const send = (data) => { + response.writeHead(200, { 'content-type': 'application/json' }); + response.end(JSON.stringify({ ok: true, data })); + }; + if (request.method === 'POST' && url === '/v1/agents') { + let parsed = {}; + try { + parsed = JSON.parse(body || '{}'); + } catch {} + send({ + id: 'agt_relayflow_broker', + workspace_id: 'ws_relayflow', + name: parsed.name ?? 'broker', + token: 'at_relayflow_broker', + status: 'online', + created_at: '2026-09-01T00:00:00.000Z', + }); + return; + } + if (url === '/v1/agents' || url === '/v1/channels') { + send([]); + return; + } + if (url.startsWith('/v1/agents/')) { + send({ id: 'agt_relayflow_other', name: 'other', status: 'offline', metadata: {} }); + return; + } + send({}); + }); +}); + +server.on('upgrade', (request, socket) => { + const key = request.headers['sec-websocket-key']; + if (!key) { + socket.destroy(); + return; + } + const accept = crypto + .createHash('sha1') + .update(key + WS_GUID) + .digest('base64'); + socket.write( + 'HTTP/1.1 101 Switching Protocols\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Accept: ' + + accept + + '\r\n\r\n' ); - // Older source revisions have no optional instrumentation handle. - if (!source.includes('pub(crate) probe:')) test = test.replace(/^\s*probe: None,\n/gm, '\n'); - if (!source.includes('mod registration_tests;')) source += '\n#[cfg(test)]\nmod registration_tests;\n'; - await writeFile(sourcePath, source); - await mkdir(path.join(checkout, 'crates/broker/src/node_control'), { recursive: true }); - await writeFile(path.join(checkout, 'crates/broker/src/node_control/registration_tests.rs'), test); - const env = { - ...process.env, - CARGO_TARGET_DIR: process.env.CARGO_TARGET_DIR ?? path.join(target, 'target'), + sockets.add(socket); + socket.on('error', () => {}); + socket.on('close', () => sockets.delete(socket)); + if (request.url.split('?')[0] !== '/v1/node/ws') return; + const session = { + registration: false, + rejected: sessions.length === 0, + closed: false, + inventory: 0, + heartbeat: 0, + other: 0, }; - for (const key of Object.keys(env)) - if (key.startsWith('GIT_CONFIG_') || key.startsWith('RELAY_ATTEST_')) delete env[key]; - const run = spawnSync( - 'cargo', + sessions.push(session); + socket.on('close', () => { + session.closed = true; + }); + socket.on( + 'data', + createFrameReader((text) => { + const frame = JSON.parse(text); + if (frame.type === 'node.register') { + session.registration = true; + const reply = session.rejected + ? { + v: 1, + type: 'error', + id: frame.id ?? 'base-registration', + ok: false, + code: 'provider_instance_conflict', + message: 'incumbent provider still live', + } + : { v: 1, type: 'reply', id: frame.id, ok: true, data: {} }; + socket.write(encodeTextFrame(JSON.stringify(reply))); + } else if (frame.type === 'inventory.sync') session.inventory++; + else if (frame.type === 'node.heartbeat') session.heartbeat++; + else session.other++; + }) + ); +}); +try { + await new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); + const port = server.address().port; + broker = spawn( + binary, [ - 'test', - '-p', - 'agent-relay-broker', - '--lib', - 'node_control::registration_tests::rejected_registration_never_advertises_or_syncs', - '--', - '--exact', + 'init', + '--instance-name', + 'registration-proof', + '--api-port', + '0', + '--api-bind', + '127.0.0.1', + '--state-dir', + state, ], - { cwd: checkout, env, encoding: 'utf8', timeout: 840000, maxBuffer: 8 * 1024 * 1024 } + { + cwd: root, + stdio: ['ignore', 'pipe', 'pipe'], + env: { + PATH: process.env.PATH, + HOME: root, + TMPDIR: root, + RELAY_API_KEY: 'rk_local_registration_proof', + RELAYCAST_BASE_URL: `http://127.0.0.1:${port}`, + RELAY_BASE_URL: `http://127.0.0.1:${port}`, + RELAY_NODE_TOKEN: 'nt_local_registration_proof', + RELAY_TELEMETRY_DISABLED: '1', + RELAY_SKIP_TELEMETRY: '1', + }, + } ); - const output = (run.stdout ?? '') + (run.stderr ?? ''); - await mkdir(path.dirname(resultPath), { recursive: true }); - await writeFile(resultPath + '.log', output); - if (run.error) throw run.error; + // Drain output without retaining peer bodies, credentials or other runtime data. + broker.stdout.resume(); + broker.stderr.resume(); let outcome, signature; - if (run.status === 0 && /1 passed; 0 failed/.test(output)) { - outcome = 'fixed'; - signature = 'rejected_registration_never_opens_delivery_path'; - } else if ( - run.status === 101 && - /registration-dependent frame escaped gate: "inventory.sync"/.test(output) && - /0 passed; 1 failed/.test(output) - ) { - outcome = 'bug'; - signature = 'rejected_registration_still_publishes_inventory'; - } else - throw Error( - `The socket regression did not reach a recognized outcome (exit ${run.status}); inspect its transcript.` - ); + const deadline = Date.now() + 120000; + while (Date.now() < deadline) { + if (broker.exitCode !== null) throw Error(`Broker exited before evidence: ${broker.exitCode}`); + const first = sessions[0]; + if (first?.registration && (first.inventory || first.heartbeat || first.other)) { + outcome = 'bug'; + signature = 'rejected_registration_still_publishes_inventory'; + break; + } + if ( + first?.registration && + first.closed && + sessions.slice(1).some((s) => s.registration && s.inventory > 0 && s.heartbeat > 0) + ) { + assert.equal(first.inventory + first.heartbeat + first.other, 0); + outcome = 'fixed'; + signature = 'rejected_registration_never_opens_delivery_path'; + break; + } + await new Promise((resolve) => setTimeout(resolve, 25)); + } + if (!outcome) throw Error('No terminal registration discriminator observed within120s.'); + await mkdir(path.dirname(resultPath), { recursive: true }); await writeFile( resultPath, JSON.stringify({ @@ -85,12 +250,21 @@ try { outcome, signature, details: - 'A real loopback WebSocket peer rejects node.register while keeping transport open. The exact target production node-control loop must disconnect without advertising Connected or sending inventory.sync; compilation and unrelated failures are not evidence.', + 'The peer rejects the first node.register and leaves its socket open. Base sends dependent frames anyway. Head closes that socket without inventory/heartbeat/ACK and reconnects; an accepted second registration then publishes inventory and heartbeat.', + sessions, }) + '\n' ); console.log(signature); } finally { - if (added) - execFileSync('git', ['-C', target, 'worktree', 'remove', '--force', checkout], { stdio: 'pipe' }); - await rm(temp, { recursive: true, force: true }); + if (broker && broker.exitCode === null) { + broker.kill('SIGTERM'); + await Promise.race([ + new Promise((resolve) => broker.once('exit', resolve)), + new Promise((resolve) => setTimeout(resolve, 3000)), + ]); + if (broker.exitCode === null) broker.kill('SIGKILL'); + } + for (const socket of sockets) socket.destroy(); + await new Promise((resolve) => server.close(resolve)); + await rm(root, { recursive: true, force: true }); } From 388ce5fe11230c7279110f0fe8c1f311958fdfa5 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:10:49 +0200 Subject: [PATCH 09/13] test(broker): observe client FIN on upgraded proof sockets Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- tests/relayflows/cases/1593-node-registration-gate/run.mjs | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/tests/relayflows/cases/1593-node-registration-gate/run.mjs b/tests/relayflows/cases/1593-node-registration-gate/run.mjs index 82f0427a93..221d8b88fa 100644 --- a/tests/relayflows/cases/1593-node-registration-gate/run.mjs +++ b/tests/relayflows/cases/1593-node-registration-gate/run.mjs @@ -159,6 +159,12 @@ server.on('upgrade', (request, socket) => { socket.on('close', () => { session.closed = true; }); + // Upgraded HTTP sockets can remain writable after peer FIN; read EOF is + // the actual client-disconnect signal, independent of our writable half. + socket.on('end', () => { + session.closed = true; + socket.end(); + }); socket.on( 'data', createFrameReader((text) => { From aa249addc73317eb8f25b838f5e07919ae76f3ba Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:27:56 +0200 Subject: [PATCH 10/13] test(broker): execute registration proof artifact without access precheck Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- tests/relayflows/cases/1593-node-registration-gate/run.mjs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/tests/relayflows/cases/1593-node-registration-gate/run.mjs b/tests/relayflows/cases/1593-node-registration-gate/run.mjs index 221d8b88fa..e39466bd85 100644 --- a/tests/relayflows/cases/1593-node-registration-gate/run.mjs +++ b/tests/relayflows/cases/1593-node-registration-gate/run.mjs @@ -4,8 +4,7 @@ import assert from 'node:assert/strict'; import crypto from 'node:crypto'; import http from 'node:http'; import { execFileSync, spawn } from 'node:child_process'; -import { mkdtemp, mkdir, writeFile, rm, access } from 'node:fs/promises'; -import { constants } from 'node:fs'; +import { mkdtemp, mkdir, writeFile, rm } from 'node:fs/promises'; import { tmpdir } from 'node:os'; import path from 'node:path'; import { fileURLToPath } from 'node:url'; @@ -28,7 +27,6 @@ assert.equal( assert.equal(gitSha(harness), required('RELAY_PR_PROOF_HEAD_SHA')); const relative = path.relative(harness, fileURLToPath(import.meta.url)); assert.ok(relative && !relative.startsWith('..') && !path.isAbsolute(relative)); -await access(binary, constants.R_OK | constants.X_OK); const root = await mkdtemp(path.join(tmpdir(), 'relayflow-registration-')); const state = path.join(root, 'state'); await mkdir(state); @@ -220,12 +218,15 @@ try { }, } ); + let spawnFailed = false; + broker.once('error', () => { spawnFailed = true; }); // Drain output without retaining peer bodies, credentials or other runtime data. broker.stdout.resume(); broker.stderr.resume(); let outcome, signature; const deadline = Date.now() + 120000; while (Date.now() < deadline) { + if (spawnFailed) throw Error('Broker artifact could not be started.'); if (broker.exitCode !== null) throw Error(`Broker exited before evidence: ${broker.exitCode}`); const first = sessions[0]; if (first?.registration && (first.inventory || first.heartbeat || first.other)) { From 6652a66143792623e165d5803553c1d1a83e0bc9 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:28:51 +0200 Subject: [PATCH 11/13] style: format broker artifact spawn failure handler Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- tests/relayflows/cases/1593-node-registration-gate/run.mjs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/relayflows/cases/1593-node-registration-gate/run.mjs b/tests/relayflows/cases/1593-node-registration-gate/run.mjs index e39466bd85..949ef93316 100644 --- a/tests/relayflows/cases/1593-node-registration-gate/run.mjs +++ b/tests/relayflows/cases/1593-node-registration-gate/run.mjs @@ -219,7 +219,9 @@ try { } ); let spawnFailed = false; - broker.once('error', () => { spawnFailed = true; }); + broker.once('error', () => { + spawnFailed = true; + }); // Drain output without retaining peer bodies, credentials or other runtime data. broker.stdout.resume(); broker.stderr.resume(); From f3f180e4f49823c0454edae4244823aada0a8841 Mon Sep 17 00:00:00 2001 From: Miya Date: Mon, 14 Sep 2026 05:41:14 +0200 Subject: [PATCH 12/13] test(broker): coordinate accepted delivery observations before peer close Session-Id: 01a09dbd-b8ff-7072-927d-2f9f2c403790 --- .../src/node_control/registration_tests.rs | 139 +++++++++++------- 1 file changed, 87 insertions(+), 52 deletions(-) diff --git a/crates/broker/src/node_control/registration_tests.rs b/crates/broker/src/node_control/registration_tests.rs index 415471a113..efb19788b1 100644 --- a/crates/broker/src/node_control/registration_tests.rs +++ b/crates/broker/src/node_control/registration_tests.rs @@ -38,6 +38,7 @@ async fn registration_gate_case(response: &str) { let accepted = response == "accept" || response == "reconfigure"; let reconfigure = response == "reconfigure"; let server_command_tx = command_tx.clone(); + let (forwarded_tx, mut forwarded_rx) = oneshot::channel(); let response = response.to_owned(); let server = tokio::spawn(async move { let (tcp, _) = listener.accept().await.unwrap(); @@ -56,9 +57,14 @@ async fn registration_gate_case(response: &str) { )) .await .unwrap(); - assert!(tokio::time::timeout(Duration::from_millis(30), ws.next()) + // A pong proves the client processed the preceding unrelated reply. + // No dependent text frame may precede this transport-only barrier. + ws.send(Message::Ping(b"registration-barrier".to_vec())) .await - .is_err()); + .unwrap(); + assert!( + matches!(ws.next().await, Some(Ok(Message::Pong(payload))) if payload == b"registration-barrier") + ); ws.send(Message::Text( json!({"v":1,"type":"reply","ok":true,"id":id,"data":{}}).to_string(), )) @@ -135,8 +141,21 @@ async fn registration_gate_case(response: &str) { for name in ["old-worker", "fresh-worker"] { ws.send(Message::Text(json!({"v":1,"type":"deliver","agent":name,"agent_id":format!("{name}-id"),"delivery_id":format!("delivery-{name}"),"msg_id":format!("message-{name}"),"seq":1,"mode":"wait","payload":{"type":"dm.received","text":"local probe"}}).to_string())).await.unwrap(); } - ws.close(None).await.unwrap(); - return; + // Keep the peer polling (and answering pings) until the runtime + // has forwarded both events. Closing immediately after send races + // the client's heartbeat write against draining buffered deliveries. + loop { + tokio::select! { + result = &mut forwarded_rx => { + result.expect("paired runtime observations completed"); + ws.close(None).await.unwrap(); + return; + } + message = ws.next() => { + assert!(matches!(message, Some(Ok(_))), "accepted client disconnected before forwarding paired events: {message:?}"); + } + } + } } if response != "timeout" { let reply = match response.as_str() { @@ -166,56 +185,72 @@ async fn registration_gate_case(response: &str) { } } }); - let result = tokio::time::timeout( - Duration::from_secs(2), - run_connected_once( - &FleetControlConfig { - ws_url, - node_token: Some("nt_test".into()), - node_id: "node-test".into(), - node_name: "test-node".into(), - broker_version: "test".into(), - token_minter: None, - session_token: None, - read_idle_timeout: Some(Duration::from_millis(150)), - probe: None, - }, - &mut command_rx, - &event_tx, - &mut registration, - &mut inventory, - &mut load, - Duration::from_millis(50), - ), - ) - .await - .expect("registration rejection/timeout must terminate the session"); - assert_eq!(result, ControlRunResult::Disconnected); - if accepted { - assert!(matches!( - event_rx.try_recv(), - Ok(FleetControlEvent::Connected) - )); - for expected in if reconfigure { - vec![] + let config = FleetControlConfig { + ws_url, + node_token: Some("nt_test".into()), + node_id: "node-test".into(), + node_name: "test-node".into(), + broker_version: "test".into(), + token_minter: None, + session_token: None, + // Only the rejection/timeout arms test the short registration deadline. + // Positive delivery completion is event-coordinated and bounded below. + read_idle_timeout: if accepted { + None } else { - vec!["old-worker", "fresh-worker"] - } { - let Ok(FleetControlEvent::Message(RelaycastToBroker::Deliver(deliver))) = - event_rx.try_recv() - else { - panic!("accepted provider must forward the paired deliveries") - }; - assert_eq!(deliver.agent, expected); - assert_eq!(deliver.msg_id, format!("message-{expected}")); + Some(Duration::from_millis(150)) + }, + probe: None, + }; + let observe = async { + if accepted { + let connected = event_rx.recv().await; + assert!( + matches!(connected, Some(FleetControlEvent::Connected)), + "accepted registration must connect: {connected:?}" + ); + if !reconfigure { + for expected in ["old-worker", "fresh-worker"] { + let event = event_rx.recv().await; + let Some(FleetControlEvent::Message(RelaycastToBroker::Deliver(deliver))) = + event + else { + panic!("accepted provider must forward {expected}; observed {event:?}"); + }; + assert_eq!(deliver.agent, expected); + assert_eq!(deliver.msg_id, format!("message-{expected}")); + } + forwarded_tx + .send(()) + .expect("accepted peer remains open until observations complete"); + } } - assert!(event_rx.try_recv().is_err(), "no duplicate deliveries"); - } else { - assert!( - !matches!(event_rx.try_recv(), Ok(FleetControlEvent::Connected)), - "transport acceptance must not report an unregistered provider connected" - ); - } + }; + let (result, ()) = tokio::time::timeout(Duration::from_secs(10), async { + tokio::join!( + run_connected_once( + &config, + &mut command_rx, + &event_tx, + &mut registration, + &mut inventory, + &mut load, + if accepted { + Duration::from_secs(60) + } else { + Duration::from_millis(50) + }, + ), + observe, + ) + }) + .await + .expect("registration case must terminate after its bounded protocol exchange"); + assert_eq!(result, ControlRunResult::Disconnected); + assert!( + event_rx.try_recv().is_err(), + "no unexpected or duplicate runtime events" + ); server .await .expect("the rejected socket emitted no dependent frames"); From f03e699e691d27540abe7e9218f7e369d4bb5a75 Mon Sep 17 00:00:00 2001 From: agentrelaybot Date: Tue, 15 Sep 2026 08:46:15 -0700 Subject: [PATCH 13/13] test(cloud): raise Windows ACL native test timeout for cold PowerShell start assertWindowsCredentialDirectory() allows up to 15s (WINDOWS_ACL_TIMEOUT_MS) for a cold powershell.exe process, but these tests relied on vitest's default 5000ms per-test timeout. Give all three tests a 20s per-test timeout so a cold PowerShell start doesn't trip CI. Co-Authored-By: Claude Sonnet 5 --- ...redential-directory-windows.native.test.ts | 74 ++++++++++++------- 1 file changed, 46 insertions(+), 28 deletions(-) diff --git a/packages/cloud/src/credential-directory-windows.native.test.ts b/packages/cloud/src/credential-directory-windows.native.test.ts index 209bcfe86d..b33e1676ee 100644 --- a/packages/cloud/src/credential-directory-windows.native.test.ts +++ b/packages/cloud/src/credential-directory-windows.native.test.ts @@ -15,33 +15,51 @@ afterEach(() => { directory = undefined; }); +// assertWindowsCredentialDirectory() shells out to a cold powershell.exe process +// and allows up to WINDOWS_ACL_TIMEOUT_MS (15_000ms) in credential-directory-windows.ts. +// Give these tests a per-test timeout comfortably above that so a cold PowerShell +// start doesn't trip vitest's default 5000ms timeout. +const WINDOWS_ACL_TEST_TIMEOUT_MS = 20_000; + describeWindows('native Windows credential directory ACL validation', () => { - it('accepts a private directory under the user profile without changing its ACL', () => { - directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-')); - expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); - }); - - it('rejects an untrusted read grant on the credential directory itself', () => { - directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-unsafe-')); - expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); - execFileSync('icacls.exe', [directory, '/grant', '*S-1-1-0:(R)'], { - stdio: 'ignore', - windowsHide: true, - }); - expect(() => assertWindowsCredentialDirectory(directory!)).toThrow( - 'Windows Relaycast credential storage requires a private directory' - ); - }); - - it('rejects an untrusted generic-all grant on the credential directory itself', () => { - directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-generic-unsafe-')); - expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); - execFileSync('icacls.exe', [directory, '/grant', '*S-1-1-0:(GA)'], { - stdio: 'ignore', - windowsHide: true, - }); - expect(() => assertWindowsCredentialDirectory(directory!)).toThrow( - 'Windows Relaycast credential storage requires a private directory' - ); - }); + it( + 'accepts a private directory under the user profile without changing its ACL', + () => { + directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-')); + expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); + }, + WINDOWS_ACL_TEST_TIMEOUT_MS + ); + + it( + 'rejects an untrusted read grant on the credential directory itself', + () => { + directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-unsafe-')); + expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); + execFileSync('icacls.exe', [directory, '/grant', '*S-1-1-0:(R)'], { + stdio: 'ignore', + windowsHide: true, + }); + expect(() => assertWindowsCredentialDirectory(directory!)).toThrow( + 'Windows Relaycast credential storage requires a private directory' + ); + }, + WINDOWS_ACL_TEST_TIMEOUT_MS + ); + + it( + 'rejects an untrusted generic-all grant on the credential directory itself', + () => { + directory = fs.mkdtempSync(path.join(os.homedir(), '.relay-acl-native-generic-unsafe-')); + expect(() => assertWindowsCredentialDirectory(directory!)).not.toThrow(); + execFileSync('icacls.exe', [directory, '/grant', '*S-1-1-0:(GA)'], { + stdio: 'ignore', + windowsHide: true, + }); + expect(() => assertWindowsCredentialDirectory(directory!)).toThrow( + 'Windows Relaycast credential storage requires a private directory' + ); + }, + WINDOWS_ACL_TEST_TIMEOUT_MS + ); });