melin_server_runtime/response.rs
1//! io_uring-based response stage — routes matching output to connections via
2//! `IORING_OP_SEND`.
3//!
4//! Replaces the blocking `write(2)` + `BufWriter` flush path with batched
5//! io_uring sends. Instead of N `write(2)` syscalls (one per dirty connection
6//! on flush), we submit N SEND SQEs in a single `io_uring_enter` call.
7//!
8//! Same SPSC consumption and journal cursor gating as `response.rs`.
9//! Runs on a dedicated OS thread.
10
11use std::collections::{HashMap, HashSet};
12use std::os::unix::io::RawFd;
13use std::sync::Arc;
14use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
15use std::sync::mpsc;
16use std::time::{Duration, Instant};
17
18use io_uring::{IoUring, opcode, types};
19use tracing::{debug, error};
20
21use melin_pipeline::ring;
22
23use crate::durability_policy::{
24 Blocker, CursorView, DurabilityMode, EvalStatus, MAX_CLUSTER_SIZE, Policy,
25};
26use crate::replication::ReplicationMetrics;
27use melin_app::Application;
28use melin_app::amortized_timer::AmortizedTimer;
29use melin_transport_core::pipeline::{OutputPayload, OutputSlot, StageUtilization};
30#[cfg(feature = "latency-trace")]
31use melin_transport_core::trace;
32use melin_transport_core::{DurableWireSeqCursor, WireSeq};
33
34use melin_wire_protocol::control::TransportResponse;
35use melin_wire_protocol::control_codec;
36
37/// Maximum number of output slots consumed per batch.
38const MAX_BATCH: usize = 1024;
39
40/// Maximum encoded response size. PositionSnapshot is the largest variant
41/// at up to 330 bytes (length(4) + tag(1) + account(4) + count(1) +
42/// 16*(currency(4)+free(8)+reserved(8))). 512 bytes covers all variants.
43const MAX_RESPONSE_BUF: usize = 512;
44
45/// io_uring submission queue depth for sends. Must be ≥ max concurrent
46/// connections to avoid SQ overflow when all connections are dirty.
47/// Power of 2 for io_uring alignment. 4096 supports 1024+ client
48/// benchmarks where all connections flush simultaneously.
49const RING_SIZE: u32 = 4096;
50
51/// Maximum accumulated send buffer per connection (64 KiB). If a client
52/// falls behind and the buffer exceeds this, the connection is dropped.
53/// 64 KiB holds ~500 response frames — well beyond any reasonable lag.
54const MAX_SEND_BUF: usize = 64 * 1024;
55
56/// Minimum interval between SEND retries to a connection whose socket
57/// buffer is full (`MSG_DONTWAIT` completed with `EAGAIN`). The stage
58/// busy-spins, so without pacing a blocked connection would cost one
59/// futile `io_uring_enter` per loop iteration. 100 µs adds no meaningful
60/// delivery delay: a full socket buffer drains at the client's read
61/// cadence (millisecond scale), and healthy connections are never paced.
62const BLOCKED_RETRY_INTERVAL: Duration = Duration::from_micros(100);
63
64/// Byte-threshold flush trigger for the consumed (busy) path — the
65/// still-open half of finding 4 in
66/// `docs/internal/latency-audit-2026-07.md`. Under sustained load with
67/// an open durability gate, neither the idle-path flush (SPSC never
68/// empties) nor the gate-path flush (no wait) runs, so without this
69/// trigger responses sit in `send_buf` until `MAX_SEND_BUF` *drops* the
70/// connection instead of serving it. Roughly one TCP MSS (1460 for
71/// standard Ethernet, minus margin): once a connection has a full
72/// segment buffered, flushing early costs nothing in wire efficiency,
73/// and the bound keeps `send_buf` ~45 flushes away from the disconnect
74/// cap instead of zero.
75const FLUSH_BYTES_THRESHOLD: usize = 1400;
76
77/// How long a connection's socket may accept *zero* bytes while it has
78/// undelivered data before it is dropped. Partial progress restarts the
79/// clock — a slow-but-draining client is `MAX_SEND_BUF`'s problem, not
80/// this one's. Complements `MAX_SEND_BUF`, which only catches clients
81/// that lag while new responses keep *arriving* — a client that stops
82/// reading during a quiet period accumulates almost nothing (heartbeats
83/// only) and would otherwise pin its buffered bytes and its slot
84/// indefinitely.
85const BLOCKED_SEND_TIMEOUT: Duration = Duration::from_secs(5);
86
87pub use crate::ControlEvent;
88
89/// Encoder type alias: response encoder bound to the application's
90/// `Report` / `QueryResponse` types. Hides the long
91/// `dyn ResponseEncoder<Report = ..., Query = ...>` at call sites.
92pub type ResponseEncoderArc<A> = Arc<
93 dyn melin_app::encoder::ResponseEncoder<
94 Report = <A as Application>::Report,
95 Query = <A as Application>::QueryResponse,
96 >,
97>;
98
99/// Configuration and shared state for the response stage.
100pub struct Response<A: Application> {
101 /// Highest wire seq durably persisted on the primary's journal.
102 /// In the same sequence space as `OutputSlot.wire_seq` and the
103 /// replica metrics (`metrics.in_memory_sequence` /
104 /// `metrics.acked_sequence`), so the durability gate can compare
105 /// these values numerically and the comparison is meaningful
106 /// regardless of `starting_sequence` (fresh vs recovered primary).
107 /// Typed [`DurableWireSeqCursor`] so the gate cannot be wired to a
108 /// ring-space counter — the pre-v14 bug class. Updated by the
109 /// journal stage after every fsync batch via `set_last_seq_publisher`.
110 pub journal_persisted_wire_seq: DurableWireSeqCursor,
111 /// Operator-selected durability mode, published through a shared
112 /// [`AtomicU8`] so the admin `DURABILITY` command can swap it at
113 /// runtime without restarting the node. The response stage reads
114 /// this once per gate iteration with a relaxed load (cheaper than a
115 /// `Mutex` or refcounted `Arc<Policy>` snapshot) and rebuilds its
116 /// local [`Policy`] when the byte changes. See
117 /// [`crate::durability_policy::DurabilityMode::as_u8`] for the
118 /// encoding.
119 pub durability_mode: Arc<std::sync::atomic::AtomicU8>,
120 /// Per-slot replica cursors. `None` for standalone deployments
121 /// (no replication wiring) — the policy then evaluates against the
122 /// primary alone.
123 pub replication_metrics: Option<Arc<ReplicationMetrics>>,
124 /// Per-slot replica active flags. Only "true" slots are included in
125 /// the cursor view fed to `Policy::evaluate`, so disconnected slots
126 /// don't pollute the view with stale zero cursors. When the
127 /// resulting view is too small to satisfy a clause, the policy
128 /// reports degraded and the gate stalls.
129 /// Mirrors `replication_metrics` — `None` in standalone.
130 pub replica_active: Option<[Arc<AtomicBool>; 2]>,
131 pub heartbeat_interval: Option<Duration>,
132 pub busy_spin: bool,
133 pub utilization: Arc<StageUtilization>,
134 /// Wire encoder for application-shaped payloads. Constructed
135 /// once at boot (`Arc::new(ExchangeResponseEncoder)`) and shared
136 /// with the DPDK response stage.
137 pub encoder: ResponseEncoderArc<A>,
138 /// Node fencing state. When latched (a higher epoch was observed), the
139 /// stage exits *without* the best-effort flush — in-flight responses
140 /// for orders on a superseded epoch must not be acknowledged. Fencing
141 /// co-sets `shutdown`, so the latch is only consulted on the shutdown
142 /// path (zero steady-state cost). See `crate::fence`.
143 pub fence_state: Arc<melin_transport_core::fence::FenceState>,
144 /// Live-connection count shared with the accept loop's
145 /// `max_connections` gate. Incremented there after auth; decremented
146 /// here — the response stage owns the connection map, so "an entry
147 /// left the map" is the one place a connection verifiably dies
148 /// exactly once, whichever side (reader disconnect or a drop
149 /// decision here) initiated it.
150 pub active_connections: Arc<AtomicU64>,
151}
152
153/// Per-connection state for batched io_uring sends.
154struct ConnectionEntry {
155 fd: RawFd,
156 /// Owns the write half of the socket to keep the fd alive.
157 _owner: Box<dyn Send>,
158 /// Accumulates encoded response frames between flushes.
159 /// The full wire frame (length prefix + payload) is appended here.
160 /// Vec's internal data pointer is heap-stable, so io_uring SEND SQEs
161 /// referencing `as_ptr()` remain valid even if the HashMap relocates
162 /// this struct. No SEND outlives its `flush_sends` call (every SQE
163 /// carries `MSG_DONTWAIT`, and the flush reaps all completions before
164 /// returning), so the Vec is never mutated while the kernel holds its
165 /// pointer.
166 send_buf: Vec<u8>,
167 /// Last time data was sent to this connection. Used for heartbeat scheduling.
168 last_send: Instant,
169 /// When this connection's socket last made zero forward progress:
170 /// set on `EAGAIN`, reset to the flush timestamp on a partial send
171 /// (bytes moved), cleared when the buffer fully drains. `None` while
172 /// the socket is accepting everything. Drives retry pacing and the
173 /// [`BLOCKED_SEND_TIMEOUT`] drop.
174 blocked_since: Option<Instant>,
175 /// Last SEND attempt. Read only while blocked, to pace retries at
176 /// [`BLOCKED_RETRY_INTERVAL`].
177 last_send_attempt: Instant,
178}
179
180/// Run the io_uring response stage loop. Blocks the calling thread until shutdown.
181///
182/// Consumes from the output SPSC, waits for durability confirmation, and
183/// sends responses via io_uring SEND.
184///
185/// Durability gating: every gate iteration reads the journal cursor
186/// (primary persisted) plus per-slot replica cursors (in-memory and
187/// persisted) from `replication_metrics` and feeds them through the
188/// configured [`Policy`]. See [`evaluate_durability`].
189pub fn run<A: Application>(
190 mut consumer: ring::Consumer<OutputSlot<A::Report, A::QueryResponse>>,
191 control_rx: mpsc::Receiver<ControlEvent>,
192 config: Response<A>,
193 shutdown: &AtomicBool,
194) {
195 let Response {
196 journal_persisted_wire_seq,
197 durability_mode,
198 replication_metrics,
199 replica_active,
200 heartbeat_interval,
201 busy_spin,
202 utilization,
203 encoder,
204 fence_state,
205 active_connections,
206 } = config;
207 // Resolve the starting mode from the shared atomic and derive the
208 // local Policy. The atomic is the single source of truth across the
209 // process lifetime; the response thread keeps a thread-local copy
210 // for cheap per-iteration use and rebuilds it when an admin
211 // `DURABILITY` command swaps the atomic. Initialise as Hybrid (the
212 // default mode) if the atomic ever holds a corrupted byte — better
213 // than panicking on a degraded process and matches the default
214 // operators see at boot.
215 let mut active_mode =
216 DurabilityMode::from_u8(durability_mode.load(std::sync::atomic::Ordering::Relaxed))
217 .unwrap_or_else(|| {
218 tracing::error!(
219 "durability_mode atomic held a corrupted byte at startup; defaulting to hybrid"
220 );
221 DurabilityMode::Hybrid
222 });
223 let mut policy = active_mode.to_policy();
224 // SINGLE_ISSUER: created and submitted from this thread only — the
225 // kernel skips SQ locking and rejects cross-thread submission with
226 // EEXIST instead of racing. Matches the journal/replication rings.
227 let mut ring: IoUring = IoUring::builder()
228 .setup_single_issuer()
229 .build(RING_SIZE)
230 .expect("failed to create io_uring instance for response stage");
231
232 // Connection table: maps connection IDs to their state.
233 // HashMap for O(1) lookup. Pre-sized for a reasonable number of concurrent clients.
234 let mut connections: HashMap<u64, ConnectionEntry> = HashMap::with_capacity(256);
235
236 let mut batch = [OutputSlot::<A::Report, A::QueryResponse>::default(); MAX_BATCH];
237 let mut encode_buf = [0u8; MAX_RESPONSE_BUF];
238
239 // Cached durability position to avoid atomic reads on every slot.
240 // Initialised below from the policy's startup evaluation; updated
241 // via `evaluate_durability` on every gate iteration.
242 let mut cached_durable_pos: u64;
243
244 // Degradation logger. Tracks transitions, suppresses sub-second
245 // flap noise, and drives the `/healthz` `policy_degraded` gauge.
246 // See `DegradationLogger` for the full state machine. Initialised
247 // below from the policy's startup evaluation so an unsatisfiable
248 // policy (e.g. a primary that just lost both replicas while
249 // running `hybrid` or `durably-replicated`) is visible immediately
250 // on `/healthz` and in the journal.
251 let startup_now = Instant::now();
252 let mut last_policy_check = startup_now;
253 /// Re-emit interval for the "still degraded" reminder.
254 const DEGRADED_LOG_INTERVAL: Duration = Duration::from_secs(5);
255 /// Cadence at which the idle path re-evaluates the policy. Bounds
256 /// the lag between a connection-state change and the `/healthz`
257 /// gauge / warn-log reflecting it. Cheap (a handful of atomic
258 /// loads + the policy evaluator) at this rate.
259 const POLICY_CHECK_INTERVAL: Duration = Duration::from_secs(1);
260 /// Cadence at which the gate-wait spin folds elapsed time into the
261 /// degraded-duration counter while the durability gate is stalled.
262 /// Tighter than the idle cadence — it bounds the boundary error when
263 /// a degradation begins or flips mid-wedge, which matters most for
264 /// short stalls. The accrual tick is gated by this period, but the
265 /// clock read behind it is gated by the `AmortizedTimer` mask, so the
266 /// effective resolution is `max(this, the mask's clock-read cadence)`.
267 /// The mask reads the clock ~every 6.5 ms at this spin's rate
268 /// (`AmortizedTimer::CHECK_MASK` is `2^16`), finer than the 10 ms
269 /// here, so this cadence is the binding one and is realized in full.
270 const GATE_ACCRUAL_INTERVAL: Duration = Duration::from_millis(10);
271
272 // Initial evaluation so the cached durable position and the
273 // `/healthz` gauge reflect the cluster's startup shape before
274 // the first batch arrives.
275 let mut degraded_logger;
276 {
277 let journal_pos = journal_persisted_wire_seq.load();
278 let metrics_ref = replication_metrics.as_deref();
279 let active_ref = replica_active.as_ref();
280 let status = evaluate_durability(&policy, journal_pos, metrics_ref, active_ref);
281 cached_durable_pos = status.durable_pos;
282 utilization
283 .policy_degraded
284 .store(status.degraded, Ordering::Relaxed);
285 degraded_logger = if status.degraded {
286 DegradationLogger::new_starting_degraded(startup_now, &policy)
287 } else {
288 DegradationLogger::new(startup_now)
289 };
290 }
291
292 // Stage histograms registered with the global registry — see
293 // `melin_transport_core::trace`. The four breakdown stages
294 // (journal-wait, replica-wait, encode, egress) feed the bench's
295 // tick-to-trade decomposition; spsc/dispatch/server-e2e are kept
296 // alongside as overall sanity checks.
297 #[cfg(feature = "latency-trace")]
298 let mut spsc_rec =
299 trace::register_stage("response: SPSC wakeup (matching publish → response consume)");
300 #[cfg(feature = "latency-trace")]
301 let mut dispatch_rec = trace::register_stage("response: dispatch (consume → socket write)");
302 #[cfg(feature = "latency-trace")]
303 let mut server_e2e_rec = trace::register_stage("server e2e (reader recv → response flush)");
304 // Tick-to-trade breakdown: per-slot wait observed for each
305 // durability path (recorded only when the gate actually held us
306 // up — cache-hit paths skip to avoid inflating the metric with
307 // crossings that happened before we noticed). Encode is wall-time
308 // around `encode_transport_response`. Egress wraps a `flush_sends`
309 // call (one sample per io_uring flush, batching many slots).
310 // Gated on `tick-to-trade`, not `latency-trace`, because these
311 // stages roughly double the hot-path mutex traffic vs the lighter
312 // 4-stage mode.
313 #[cfg(feature = "tick-to-trade")]
314 let mut journal_wait_rec =
315 trace::register_stage("response: journal-wait (match_complete → journal cursor crossed)");
316 #[cfg(feature = "tick-to-trade")]
317 let mut replica_wait_rec = trace::register_stage(
318 "response: replica-wait (match_complete → replication cursor crossed)",
319 );
320 #[cfg(feature = "tick-to-trade")]
321 let mut encode_rec = trace::register_stage("response: encode (per-kind wire encoding)");
322 #[cfg(feature = "tick-to-trade")]
323 let mut egress_rec = trace::register_stage("response: egress (flush_sends elapsed)");
324 // Paces the idle-path recorder flush. Without it, every sample this
325 // thread recorded stays in its thread-local buffer once traffic
326 // stops — which is exactly when the bench scrapes /stats-dump.
327 #[cfg(feature = "latency-trace")]
328 let mut last_stats_flush = Instant::now();
329
330 // Server-side end-to-end samples awaiting a flush, tagged with the
331 // connection whose bytes they measure.
332 //
333 // The stage encodes into `send_buf` and hands the bytes to the
334 // kernel later, so closing the sample at encode time would omit
335 // every microsecond a response spends buffered — the interval this
336 // stage most needs to be honest about, since that is exactly where a
337 // deferred flush hides. Holding each frame's `recv_ts` until the
338 // flush completes measures reader-recv → kernel, which is what the
339 // stage name claims and what the DPDK path already records (it
340 // samples after `tx_producers.flush()`).
341 //
342 // The connection id is what lets a connection dropped without a
343 // flush have its samples thrown away rather than closed — see
344 // `discard_e2e_samples`. Two rules keep the queue honest, and every
345 // mutation of `dirty_connections` obeys one of them:
346 //
347 // - a clear-by-flush closes the queue (`close_e2e_samples`),
348 // - a removal-by-drop discards that connection's entries
349 // (`discard_e2e_samples`).
350 //
351 // Together they give the invariant "queue non-empty implies some
352 // connection is dirty", which is what makes the flush sites
353 // sufficient drain points.
354 //
355 // `Vec` rather than a per-connection map: entries are appended and
356 // then walked wholesale, order is irrelevant, and the dropped-
357 // connection lists they are matched against are almost always empty.
358 // A flat append is the cheapest thing that does that. Capacity is a
359 // starting point, not a bound — under saturation the output ring
360 // never empties, so the queue grows until something forces a flush.
361 //
362 // Only compiled under `latency-trace`; production builds carry
363 // neither the buffer nor the pushes.
364 #[cfg(feature = "latency-trace")]
365 let mut pending_e2e: Vec<(u64, trace::MonoTraceInstant)> = Vec::with_capacity(MAX_BATCH);
366
367 // Track connections with buffered (unflushed) writes across batches.
368 let mut dirty_connections: HashSet<u64> = HashSet::new();
369
370 // Connections to remove after flush (send errors).
371 let mut to_remove: Vec<u64> = Vec::new();
372
373 // Pre-allocated CQE collection buffer. Must collect CQEs before
374 // processing because the CQ borrow must end before mutating connections.
375 // Pre-sized to RING_SIZE to avoid per-iteration heap allocation.
376 let mut cqes: Vec<(u64, i32)> = Vec::with_capacity(RING_SIZE as usize);
377
378 // Pre-encode the heartbeat response frame once. Full wire frame
379 // (length prefix + tag) for direct append to send_buf.
380 let heartbeat_wire_frame = {
381 let mut buf = [0u8; 8];
382 let written =
383 control_codec::encode_transport_response(&TransportResponse::Heartbeat, &mut buf)
384 .expect("heartbeat encodes");
385 buf[..written].to_vec()
386 };
387
388 // Pre-encode the ServerBusy frame the same way. Sent on behalf of
389 // the reader (`ControlEvent::PipelineBusy`) — this stage owns all
390 // egress on a client socket, so the busy notice appends to
391 // `send_buf` like any other frame instead of racing our sends from
392 // the reader thread.
393 let server_busy_wire_frame = {
394 let mut buf = [0u8; 8];
395 let written =
396 control_codec::encode_transport_response(&TransportResponse::ServerBusy, &mut buf)
397 .expect("ServerBusy encodes");
398 buf[..written].to_vec()
399 };
400
401 // Coarse timestamp for heartbeat scan — avoids Instant::now() on every spin.
402 let mut last_heartbeat_scan = Instant::now();
403
404 // Adaptive spin: spin first (fast wakeup), yield after threshold.
405 let mut idle_spins: u32 = 0;
406
407 let mut busy_count: u64 = 0;
408 let mut idle_count: u64 = 0;
409
410 // Paces accrual ticks inside the durability gate-wait spin so the
411 // degraded-duration counter keeps advancing during a hard stall.
412 // Declared once at function scope (not per gate entry) so the normal
413 // gated path — entered briefly whenever durability lags by a few µs —
414 // pays no extra `Instant::now()`; the amortized mask only reads the
415 // clock once per ~1 M cumulative spin iterations.
416 let mut gate_accrual_timer = AmortizedTimer::new();
417
418 loop {
419 // Observe runtime mode swaps from the admin `DURABILITY`
420 // command. Relaxed load (single writer is the admin handler,
421 // single reader is this thread). When the byte changes,
422 // rebuild the local Policy and reset the cached durable
423 // position so the next gate evaluation starts from a clean
424 // slate under the new shape; log the transition for the audit
425 // trail. An unknown byte is treated as memory corruption: we
426 // log and keep the prior mode rather than silently downgrading.
427 let observed_byte = durability_mode.load(Ordering::Relaxed);
428 if observed_byte != active_mode.as_u8() {
429 match DurabilityMode::from_u8(observed_byte) {
430 Some(next) => {
431 tracing::info!(
432 prev = active_mode.as_str(),
433 next = next.as_str(),
434 "durability mode swapped at runtime"
435 );
436 active_mode = next;
437 policy = active_mode.to_policy();
438 // The fresh policy may evaluate degraded/undegraded
439 // differently against the same cluster shape; let
440 // the next gate evaluation re-derive.
441 cached_durable_pos = 0;
442 // Re-seed the degradation logger so a transition
443 // out of (or into) degraded under the new policy
444 // surfaces immediately rather than waiting for the
445 // sustained-state hold to roll over. Flushes accrual
446 // first so pre-swap degraded time isn't dropped.
447 degraded_logger.reseed(&utilization, Instant::now());
448 }
449 None => {
450 tracing::error!(
451 byte = observed_byte,
452 "durability_mode atomic held a corrupted byte; retaining prior mode"
453 );
454 }
455 }
456 }
457
458 if shutdown.load(Ordering::Relaxed) {
459 // Fence: a superseded ex-primary must not acknowledge any
460 // further in-flight work — skip the best-effort flush so
461 // responses buffered for orders on the old epoch are dropped
462 // (the client sees a connection reset and reconciles on
463 // reconnect). Checked only here, not per iteration: fencing
464 // always co-sets `shutdown` (`FenceState::fence_if_superseded`
465 // owns that invariant), so this branch is the first one a
466 // fenced node reaches and the steady-state loop pays nothing.
467 let flush = !fence_state.is_fenced();
468 // Best-effort flush before shutdown.
469 if flush && !dirty_connections.is_empty() {
470 flush_sends(
471 &mut ring,
472 &mut connections,
473 &mut dirty_connections,
474 &mut to_remove,
475 &mut cqes,
476 );
477 #[cfg(feature = "latency-trace")]
478 close_e2e_samples(&mut pending_e2e, &mut server_e2e_rec);
479 }
480 utilization.busy.store(busy_count, Ordering::Relaxed);
481 utilization.idle.store(idle_count, Ordering::Relaxed);
482 #[cfg(feature = "pipeline-stats")]
483 print_utilization("response", busy_count, idle_count);
484 return;
485 }
486
487 // Poll control channel (non-blocking) for connect/disconnect.
488 while let Ok(event) = control_rx.try_recv() {
489 match event {
490 ControlEvent::Connected {
491 connection_id,
492 fd,
493 writer,
494 } => {
495 // The writer keeps the fd alive — store it as the owner.
496 let owner: Box<dyn Send> = Box::new(writer);
497 connections.insert(
498 connection_id,
499 ConnectionEntry {
500 fd,
501 _owner: owner,
502 send_buf: Vec::with_capacity(4096),
503 last_send: Instant::now(),
504 blocked_since: None,
505 last_send_attempt: Instant::now(),
506 },
507 );
508 }
509 ControlEvent::Disconnected { connection_id } => {
510 // Reader-initiated teardown: the reader already
511 // closed its half. Decrement only if the entry was
512 // actually present — a response-initiated drop
513 // already removed it (and paid the decrement), and
514 // this event is its echo.
515 if connections.remove(&connection_id).is_some() {
516 active_connections.fetch_sub(1, Ordering::Relaxed);
517 }
518 dirty_connections.remove(&connection_id);
519 // Anything this connection had buffered goes with
520 // it, so its queued samples measure bytes that will
521 // never be sent.
522 #[cfg(feature = "latency-trace")]
523 discard_e2e_samples(&mut pending_e2e, &[connection_id]);
524 }
525 ControlEvent::PipelineBusy { connection_id } => {
526 if let Some(entry) = connections.get_mut(&connection_id) {
527 // Overflow discipline: a busy notice to a peer
528 // already at its buffer cap is not worth more
529 // memory — skip it; the cap (or the blocked
530 // timeout) is about to drop the connection
531 // anyway. Missing entry likewise: best-effort.
532 if entry.send_buf.len() + server_busy_wire_frame.len() <= MAX_SEND_BUF {
533 entry.send_buf.extend_from_slice(&server_busy_wire_frame);
534 entry.last_send = Instant::now();
535 dirty_connections.insert(connection_id);
536 }
537 }
538 }
539 }
540 }
541
542 // Consume output slots from matching stage.
543 let count = consumer.consume_batch(&mut batch, MAX_BATCH);
544 if count == 0 {
545 // SPSC is empty — flush all dirty connections via io_uring.
546 // This is the response-data egress path; heartbeat flushes
547 // below aren't sampled because they're admin traffic, not
548 // on the client RTT path.
549 if !dirty_connections.is_empty() {
550 #[cfg(feature = "tick-to-trade")]
551 let egress_start = trace::mono_trace_ns();
552 flush_sends(
553 &mut ring,
554 &mut connections,
555 &mut dirty_connections,
556 &mut to_remove,
557 &mut cqes,
558 );
559 #[cfg(feature = "tick-to-trade")]
560 egress_rec.record_elapsed(egress_start, trace::mono_trace_ns());
561 #[cfg(feature = "latency-trace")]
562 close_e2e_samples(&mut pending_e2e, &mut server_e2e_rec);
563 for conn_id in to_remove.drain(..) {
564 if let Some(entry) = connections.remove(&conn_id) {
565 teardown_dropped(entry, &active_connections);
566 }
567 }
568 }
569
570 // Send heartbeats to idle connections. Only checked during
571 // idle periods (SPSC empty) to avoid overhead on the hot path.
572 //
573 // No end-to-end samples to close here: the sample queue's
574 // invariant is that a queued entry implies a dirty
575 // connection, so the flush above — which closes the queue
576 // whenever anything was dirty — leaves it empty. Anything
577 // dirtied from here on is heartbeat frames, which carry no
578 // samples.
579 if let Some(interval) = heartbeat_interval {
580 let now = Instant::now();
581 // Coarse gate: only scan at most once per second.
582 if now.duration_since(last_heartbeat_scan) >= Duration::from_secs(1) {
583 last_heartbeat_scan = now;
584 for (&conn_id, entry) in connections.iter_mut() {
585 if heartbeat_due(entry, now, interval, heartbeat_wire_frame.len()) {
586 entry.send_buf.extend_from_slice(&heartbeat_wire_frame);
587 dirty_connections.insert(conn_id);
588 entry.last_send = now;
589 }
590 }
591 // Flush the heartbeat sends immediately.
592 if !dirty_connections.is_empty() {
593 flush_sends(
594 &mut ring,
595 &mut connections,
596 &mut dirty_connections,
597 &mut to_remove,
598 &mut cqes,
599 );
600 for conn_id in to_remove.drain(..) {
601 if let Some(entry) = connections.remove(&conn_id) {
602 teardown_dropped(entry, &active_connections);
603 }
604 }
605 }
606 }
607 }
608
609 // Re-evaluate the durability policy on a slow timer so the
610 // `policy_degraded` flag and the periodic warn track the
611 // cluster's real state even on idle / quiet venues. The
612 // gate-open block also calls `update_degraded_state` after
613 // each consumed batch; this is the equivalent for the
614 // no-batch path.
615 {
616 let now_ts = Instant::now();
617 if now_ts.duration_since(last_policy_check) >= POLICY_CHECK_INTERVAL {
618 last_policy_check = now_ts;
619 let journal_pos = journal_persisted_wire_seq.load();
620 let metrics_ref = replication_metrics.as_deref();
621 let active_ref = replica_active.as_ref();
622 let status = evaluate_durability(&policy, journal_pos, metrics_ref, active_ref);
623 degraded_logger.tick(
624 &policy,
625 &utilization,
626 status.degraded,
627 now_ts,
628 DEGRADED_LOG_INTERVAL,
629 );
630 // Cache the position so the next batch's gate sees a
631 // fresh value rather than spinning from a stale cache.
632 cached_durable_pos = status.durable_pos;
633 }
634
635 // Hand buffered latency samples to the stats registry
636 // while we have nothing better to do. Reuses the policy
637 // check's clock read, so the spin path picks up no
638 // extra `clock_gettime`.
639 #[cfg(feature = "latency-trace")]
640 if now_ts.duration_since(last_stats_flush) >= trace::IDLE_FLUSH_INTERVAL {
641 last_stats_flush = now_ts;
642 spsc_rec.flush();
643 dispatch_rec.flush();
644 server_e2e_rec.flush();
645 #[cfg(feature = "tick-to-trade")]
646 {
647 journal_wait_rec.flush();
648 replica_wait_rec.flush();
649 encode_rec.flush();
650 egress_rec.flush();
651 }
652 }
653 }
654
655 idle_count += 1;
656 if idle_count.is_multiple_of(1024) {
657 utilization.busy.store(busy_count, Ordering::Relaxed);
658 utilization.idle.store(idle_count, Ordering::Relaxed);
659 }
660 if busy_spin || idle_spins < 1000 {
661 idle_spins = idle_spins.wrapping_add(1);
662 std::hint::spin_loop();
663 } else {
664 std::thread::yield_now();
665 }
666 continue;
667 }
668 idle_spins = 0;
669 busy_count += 1;
670
671 #[cfg(feature = "latency-trace")]
672 let consume_ts = trace::mono_trace_ns();
673
674 // Wait for durability confirmation before sending responses.
675 //
676 // Gate on `wire_seq`, not `input_seq`. `input_seq` is in
677 // local-consumer space (the matching cursor on the input ring,
678 // starts at 0 in this process) while replica metrics and the
679 // primary's `journal_persisted_wire_seq` live in wire-seq space
680 // (allocated by the journal stage starting at
681 // `starting_sequence`). A `needed` derived from `input_seq` and
682 // compared against wire-seq cursors only works when
683 // `starting_sequence == 1`; a recovered primary (or any process
684 // whose journal already has prior content pushing
685 // `starting_sequence` above 1) would silently open the gate
686 // ahead of the replica's actual replicated state.
687 //
688 // Every cursor in the policy view (`journal_persisted_wire_seq`,
689 // `metrics.in_memory_sequence`, `metrics.acked_sequence`)
690 // carries "highest wire seq known to be in that state on node
691 // X". A slot's `wire_seq` is therefore the *exact* wire seq the
692 // gate must see — not `+1` — for that slot's event to be
693 // considered durable. The legacy `+1` was load-bearing only
694 // because `input_seq` was off by `starting_sequence - 1` from
695 // wire seq; with the wire-seq stamp it would over-shoot by one
696 // event and make the gate stall an extra round-trip per
697 // response.
698 //
699 // The gate is evaluated **per slot**, not once per batch against
700 // the batch's maximum `wire_seq`. Batch-max gating made every
701 // response in a batch wait for the newest event in it to become
702 // durable, so the oldest slot paid the durability latency of an
703 // event sequenced up to `MAX_BATCH` positions after it — a
704 // head-of-line block bounded only by the batch size, and one
705 // that bites hardest exactly when the stage has caught up to the
706 // durability frontier under load. Per-slot gating walks that
707 // frontier instead: each response is released as soon as its own
708 // event is durable.
709 //
710 // The extra waits are self-limiting. Slots arrive FIFO with
711 // monotonic `wire_seq`, and the journal publishes its cursor per
712 // fsync batch, so one wait typically advances the cursor past a
713 // whole run of following slots and they fall through without
714 // spinning. The number of waits (and so of flushes) tracks real
715 // durability boundaries, not the slot count. Correctness does
716 // not depend on that ordering — an unsorted batch would simply
717 // wait more often.
718 let batch_now = Instant::now();
719
720 // Set when a connection's send_buf crosses
721 // FLUSH_BYTES_THRESHOLD; checked after every slot so the flush
722 // runs *within* the batch. Deferring it to the end of the batch
723 // would reopen the defect the threshold exists to close: one
724 // MAX_BATCH batch of large frames (anything over ~64 bytes
725 // average) can push a healthy connection from empty past
726 // `MAX_SEND_BUF` before a batch-end flush ever ran, tearing it
727 // down with nothing written. A flag written at append time
728 // rather than a per-slot scan of the dirty set: the scan would
729 // cost a hash lookup per dirty connection on the hot path.
730 let mut flush_due = false;
731
732 for slot in &batch[..count] {
733 #[cfg(feature = "latency-trace")]
734 spsc_rec.record_elapsed(slot.match_complete_ts, consume_ts);
735
736 // Per-slot journal-wait / replica-wait tracker. See
737 // `GateCrossTracker` for the rationale (only records cursors
738 // that were actually on the critical path). Both the
739 // tracker's replica cursor and the attribution counters
740 // below are derived from the policy in force rather than a
741 // fixed level, so "which subsystem to optimize" answers for
742 // the deployment the operator actually configured. A slot
743 // that never waits leaves the tracker unobserved, and an
744 // unobserved tracker reports no crossing — so the fast path
745 // records nothing rather than a zero-length sample.
746 #[cfg(feature = "tick-to-trade")]
747 let mut gate_tracker = GateCrossTracker::new(slot.wire_seq);
748
749 if slot_needs_gate(slot, cached_durable_pos) {
750 let needed = slot.wire_seq;
751
752 // Drain buffered sends before blocking, never after.
753 //
754 // The steady-state flush happens on the `count == 0`
755 // path — once the output ring is empty. That batches
756 // many responses behind one `io_uring_enter`, which is
757 // the right trade on the fast path. But it means a
758 // response that has already cleared its own durability
759 // gate stays in `send_buf` while the loop blocks on a
760 // later event's gate, so a client waits out an fsync +
761 // replica round-trip for an event whose durability was
762 // confirmed before that event was even sequenced.
763 //
764 // Flushing here costs nothing in latency terms: it only
765 // fires when we are about to spin on the gate anyway, so
766 // the syscall overlaps time that would otherwise be
767 // dead. Slots whose gate is already satisfied fall
768 // straight through and keep their batching.
769 //
770 // Traced builds only: this delays the tracker's first
771 // `observe` by the flush duration, so a cursor that
772 // crosses mid-flush is attributed late (or, if it
773 // crosses past `needed`, not attributed at all). Bounded
774 // by one flush and confined to the tick-to-trade
775 // breakdown — the gate's own behaviour is unchanged.
776 if !dirty_connections.is_empty() {
777 #[cfg(feature = "tick-to-trade")]
778 let egress_start = trace::mono_trace_ns();
779 flush_sends(
780 &mut ring,
781 &mut connections,
782 &mut dirty_connections,
783 &mut to_remove,
784 &mut cqes,
785 );
786 #[cfg(feature = "tick-to-trade")]
787 egress_rec.record_elapsed(egress_start, trace::mono_trace_ns());
788 #[cfg(feature = "latency-trace")]
789 close_e2e_samples(&mut pending_e2e, &mut server_e2e_rec);
790 // This slot and later ones addressed to a dropped
791 // connection are skipped by the
792 // `connections.get_mut` lookup below, so removing
793 // here is safe.
794 for conn_id in to_remove.drain(..) {
795 if let Some(entry) = connections.remove(&conn_id) {
796 teardown_dropped(entry, &active_connections);
797 }
798 }
799 }
800
801 loop {
802 // Inside the gate-wait spin loop, also observe a
803 // mode swap. Without this, a batch whose gate
804 // becomes structurally unsatisfiable (e.g. all
805 // replicas die while a non-bypass slot is in
806 // flight under `Hybrid`) would wedge the response
807 // stage forever, even if an operator sends the
808 // remediating `DURABILITY local` — the outer loop
809 // observation never gets a chance to run. The
810 // relaxed load is ~1 cycle on x86; cheaper than
811 // the `spin_loop` hint below.
812 let observed_byte = durability_mode.load(Ordering::Relaxed);
813 if observed_byte != active_mode.as_u8()
814 && let Some(next) = DurabilityMode::from_u8(observed_byte)
815 {
816 tracing::info!(
817 prev = active_mode.as_str(),
818 next = next.as_str(),
819 "durability mode swapped during gate wait"
820 );
821 active_mode = next;
822 policy = active_mode.to_policy();
823 // Flush accrual before re-seeding so the wedged-
824 // degraded interval up to the swap isn't dropped.
825 degraded_logger.reseed(&utilization, Instant::now());
826 }
827
828 let journal_pos = journal_persisted_wire_seq.load();
829 let metrics_ref = replication_metrics.as_deref();
830 let active_ref = replica_active.as_ref();
831
832 // The cross-tracker (traced builds only) samples the
833 // replica cursor itself rather than sharing the
834 // evaluation's read below: computing a standalone
835 // replica cursor unconditionally spent four Acquire
836 // loads per spin iteration on `ReplicationMetrics`,
837 // the same cache line the replication sender writes
838 // on every ack and every completed SEND. Gate
839 // attribution does not re-read at all — it comes out
840 // of `evaluate_gate`, from the same snapshot that
841 // opens the gate.
842 #[cfg(feature = "tick-to-trade")]
843 gate_tracker.observe(
844 journal_pos.get(),
845 // The level the *active policy* gates replicas
846 // on — in-memory under `hybrid`, persisted under
847 // `durably-replicated`. `None` when no clause is
848 // replica-supplied (`local`) and, transiently,
849 // when the binding replica drops out of the
850 // cursor view mid-wait. Passed through as-is so
851 // the tracker can tell "no replica wait to
852 // measure" from "the replica caught up".
853 policy_replica_cursor(&policy, journal_pos, metrics_ref, active_ref),
854 trace::mono_trace_ns(),
855 );
856
857 let (status, blocker) =
858 evaluate_gate(&policy, needed, journal_pos, metrics_ref, active_ref);
859 cached_durable_pos = status.durable_pos;
860 utilization
861 .policy_degraded
862 .store(status.degraded, Ordering::Relaxed);
863
864 // Accrue degraded time while wedged. The post-gate
865 // tick attributes the whole wait to a single state, so
866 // without this a healthy→degraded flip during the
867 // wedge would be mis-charged. `spinning = true`: this
868 // loop always spins (never yields), so the clock read
869 // behind the tick is mask-gated, landing only every
870 // ~65 k iterations (`CHECK_MASK = 2^16`) regardless of
871 // the period below.
872 if gate_accrual_timer
873 .tick(GATE_ACCRUAL_INTERVAL, true)
874 .is_some()
875 {
876 degraded_logger.tick(
877 &policy,
878 &utilization,
879 status.degraded,
880 Instant::now(),
881 DEGRADED_LOG_INTERVAL,
882 );
883 }
884
885 if cached_durable_pos >= needed {
886 // Attribution: which subsystem supplied the
887 // binding cursor, from the same snapshot that
888 // opened the gate and against the policy
889 // actually in force. Relaxed is fine — health
890 // reads are infrequent.
891 //
892 // `None` is unreachable here: `needed >= 1`
893 // inside this loop, and a degraded evaluation
894 // pins `durable_pos` to 0, so an open gate
895 // implies the policy was satisfiable and
896 // attribution has a verdict. The no-op arm
897 // keeps a metrics-only path from ever
898 // panicking regardless.
899 match blocker {
900 Some(Blocker::Journal) => {
901 utilization.gate_journal.fetch_add(1, Ordering::Relaxed);
902 }
903 Some(Blocker::Replication) => {
904 utilization.gate_replication.fetch_add(1, Ordering::Relaxed);
905 }
906 None => {}
907 }
908 break;
909 }
910 std::hint::spin_loop();
911 }
912 }
913
914 // Per-slot durability-gate breakdown. Recorded only when the
915 // gate actually held us up (the tracker captured a cross).
916 // The cross timestamp is this slot's own `wire_seq`, so the
917 // sample measures the wait that slot really paid — under
918 // batch-max gating it was the batch maximum's crossing,
919 // which overstated every slot but the last by up to the
920 // batch's matching span.
921 #[cfg(feature = "tick-to-trade")]
922 if let Some(ts) = gate_tracker.journal_crossed() {
923 journal_wait_rec.record_elapsed(slot.match_complete_ts, ts);
924 }
925 #[cfg(feature = "tick-to-trade")]
926 if let Some(ts) = gate_tracker.replica_crossed() {
927 replica_wait_rec.record_elapsed(slot.match_complete_ts, ts);
928 }
929
930 // Each slot expands to at most two wire frames: the
931 // application payload (Report / Query / EngineError) and
932 // an optional trailing `BatchEnd` when
933 // `is_last_in_request` is set. Application-shaped
934 // payloads go through the encoder; transport-shaped
935 // frames (EngineError, BatchEnd) are encoded by the
936 // runtime directly.
937 if let Some(entry) = connections.get_mut(&slot.connection_id) {
938 // Frame 1: application payload (if any). BatchEnd
939 // payloads carry no body — the terminator below
940 // handles them via `is_last_in_request`.
941 let payload_result: Option<Result<usize, &'static str>> = match slot.payload {
942 OutputPayload::Report(ref report) => {
943 Some(encoder.encode_report(report, &mut encode_buf))
944 }
945 OutputPayload::QueryResponse(ref q) => {
946 Some(encoder.encode_query(q, &mut encode_buf))
947 }
948 OutputPayload::EngineError => Some(
949 control_codec::encode_transport_response(
950 &TransportResponse::EngineError,
951 &mut encode_buf,
952 )
953 .map_err(|_| "encode error"),
954 ),
955 OutputPayload::BatchEnd => None,
956 };
957
958 let payload_handled = if let Some(result) = payload_result {
959 #[cfg(feature = "tick-to-trade")]
960 let encode_start = trace::mono_trace_ns();
961 let outcome = append_frame(
962 result,
963 slot.connection_id,
964 entry,
965 &encode_buf,
966 batch_now,
967 &mut dirty_connections,
968 &mut to_remove,
969 );
970 #[cfg(feature = "tick-to-trade")]
971 encode_rec.record_elapsed(encode_start, trace::mono_trace_ns());
972 outcome
973 } else {
974 AppendOutcome::Continue
975 };
976
977 // Frame 2: BatchEnd terminator. Skipped if the payload
978 // append dropped the connection.
979 if matches!(payload_handled, AppendOutcome::Continue) && slot.is_last_in_request {
980 let result = control_codec::encode_transport_response(
981 &TransportResponse::BatchEnd,
982 &mut encode_buf,
983 )
984 .map_err(|_| "encode error");
985 let outcome = append_frame(
986 result,
987 slot.connection_id,
988 entry,
989 &encode_buf,
990 batch_now,
991 &mut dirty_connections,
992 &mut to_remove,
993 );
994 // Queue the server-side end-to-end sample: reader
995 // recv -> response flush. Only the BatchEnd frame
996 // carries this measurement; queued here after the
997 // append so a dropped connection doesn't skew the
998 // metric, and closed by whichever flush ships the
999 // bytes.
1000 #[cfg(feature = "latency-trace")]
1001 if matches!(outcome, AppendOutcome::Continue) {
1002 pending_e2e.push((slot.connection_id, slot.recv_ts));
1003 }
1004 let _ = outcome;
1005 }
1006
1007 flush_due |= entry.send_buf.len() >= FLUSH_BYTES_THRESHOLD;
1008 }
1009
1010 // Byte-threshold flush on the consumed path — the still-
1011 // open half of July-audit finding 4. Under sustained load
1012 // with an open gate this is the ONLY flush that runs: the
1013 // idle path needs an empty SPSC, the gate path needs a
1014 // durability wait, and heartbeats need idleness. Without
1015 // it, delivery on a busy stretch degenerates to
1016 // `MAX_SEND_BUF` evicting the very clients being served.
1017 // Threshold-gated so light traffic keeps full batching;
1018 // once a connection holds ~an MSS the extra submit no
1019 // longer costs wire efficiency. MSG_DONTWAIT flushes cannot
1020 // block, so this adds no head-of-line exposure (the hazard
1021 // that deferred this trigger in July). Runs between slots,
1022 // not after the batch, so `MAX_SEND_BUF` can never trip on
1023 // a healthy connection within a single batch — a blocked
1024 // peer re-arms the flag on its later slots, but its paced
1025 // retry inside `flush_sends` keeps that cheap.
1026 if flush_due {
1027 flush_due = false;
1028 // Overflow-dropped connections leave first so the flush
1029 // skips them — same order as the batch-end cleanup, and
1030 // their queued samples go with them (they measure bytes
1031 // that will never be flushed). Later slots addressed to
1032 // them are skipped by the `connections.get_mut` miss
1033 // above.
1034 #[cfg(feature = "latency-trace")]
1035 discard_e2e_samples(&mut pending_e2e, &to_remove);
1036 for conn_id in to_remove.drain(..) {
1037 if let Some(entry) = connections.remove(&conn_id) {
1038 teardown_dropped(entry, &active_connections);
1039 }
1040 dirty_connections.remove(&conn_id);
1041 }
1042 #[cfg(feature = "tick-to-trade")]
1043 let egress_start = trace::mono_trace_ns();
1044 flush_sends(
1045 &mut ring,
1046 &mut connections,
1047 &mut dirty_connections,
1048 &mut to_remove,
1049 &mut cqes,
1050 );
1051 #[cfg(feature = "tick-to-trade")]
1052 egress_rec.record_elapsed(egress_start, trace::mono_trace_ns());
1053 #[cfg(feature = "latency-trace")]
1054 close_e2e_samples(&mut pending_e2e, &mut server_e2e_rec);
1055 for conn_id in to_remove.drain(..) {
1056 if let Some(entry) = connections.remove(&conn_id) {
1057 teardown_dropped(entry, &active_connections);
1058 }
1059 }
1060 }
1061 }
1062
1063 // Remove connections that exceeded the send buffer limit. Like
1064 // the disconnect handler, this un-dirties a connection without
1065 // flushing it, so it has to discard that connection's queued
1066 // samples too — otherwise they outlive the bytes they measure
1067 // and land on some later, unrelated flush.
1068 #[cfg(feature = "latency-trace")]
1069 discard_e2e_samples(&mut pending_e2e, &to_remove);
1070 for conn_id in to_remove.drain(..) {
1071 if let Some(entry) = connections.remove(&conn_id) {
1072 teardown_dropped(entry, &active_connections);
1073 }
1074 dirty_connections.remove(&conn_id);
1075 }
1076
1077 // Log degradation transitions / re-emit the reminder. Same
1078 // logger the idle path uses; transitions are gated on a
1079 // sustained-state hold so sub-second flap doesn't spam.
1080 //
1081 // Ticked after dispatch rather than before it, and off a fresh
1082 // clock read: with the gate now evaluated per slot, a batch can
1083 // span several waits, and `batch_now` was taken before the first
1084 // of them. The accrual inside each wait already charges degraded
1085 // time as it elapses; this tick decides transitions, so it wants
1086 // the state and the timestamp as of the end of the batch.
1087 let ticked_at = Instant::now();
1088 let degraded_now = utilization.policy_degraded.load(Ordering::Relaxed);
1089 degraded_logger.tick(
1090 &policy,
1091 &utilization,
1092 degraded_now,
1093 ticked_at,
1094 DEGRADED_LOG_INTERVAL,
1095 );
1096 // Bump the idle-path's check timestamp so we don't double-
1097 // tick the logger when traffic stops.
1098 last_policy_check = ticked_at;
1099
1100 #[cfg(feature = "latency-trace")]
1101 dispatch_rec.record_elapsed(consume_ts, trace::mono_trace_ns());
1102 }
1103}
1104
1105/// Close every queued server-side end-to-end sample against the flush
1106/// that just completed. Call immediately after `flush_sends`.
1107///
1108/// Closes the whole queue unconditionally, including entries for a
1109/// connection the flush then dropped on a send error. That is
1110/// deliberate: the stage measures "reader recv → response flush", which
1111/// ends when the bytes are handed to the kernel, not when the peer
1112/// acknowledges them. A failed SEND still produces a sample whose
1113/// duration is the real one for everything this stage controls.
1114/// Contrast [`discard_e2e_samples`], where no flush happens at all.
1115///
1116/// One clock read serves the whole queue: the samples all end at the
1117/// same flush, so reading per entry would only measure the drain loop.
1118#[cfg(feature = "latency-trace")]
1119fn close_e2e_samples(
1120 pending: &mut Vec<(u64, trace::MonoTraceInstant)>,
1121 rec: &mut trace::StageRecorder,
1122) {
1123 let flushed_at = trace::mono_trace_ns();
1124 for (_, recv_ts) in pending.drain(..) {
1125 rec.record_elapsed(recv_ts, flushed_at);
1126 }
1127}
1128
1129/// Drop queued samples belonging to connections going away *without* a
1130/// flush — the disconnect handler and the send-buffer-overflow drain.
1131///
1132/// Their buffered bytes are discarded along with the connection, so
1133/// there is no flush to close the samples against and nothing to
1134/// measure. Left queued, they would instead be timed against some later,
1135/// unrelated connection's flush: a millisecond-scale phantom in a
1136/// microsecond histogram, landing squarely in the tail this stage exists
1137/// to report.
1138///
1139/// Not to be used after `flush_sends`. `dropped` there can hold a
1140/// connection queued by an earlier append overflow whose buffered bytes
1141/// the flush nonetheless shipped — discarding would lose a legitimate
1142/// sample.
1143///
1144/// Linear scan per entry, but `dropped` is empty on every iteration that
1145/// loses no connection, which is essentially all of them, and the early
1146/// return keeps that case free.
1147#[cfg(feature = "latency-trace")]
1148fn discard_e2e_samples(pending: &mut Vec<(u64, trace::MonoTraceInstant)>, dropped: &[u64]) {
1149 if dropped.is_empty() {
1150 return;
1151 }
1152 pending.retain(|(conn_id, _)| !dropped.contains(conn_id));
1153}
1154
1155/// Whether this slot must wait on the durability gate before its
1156/// response is encoded.
1157///
1158/// Two reasons to skip the wait. First, the durability-gate carve-out
1159/// for halt-state output: slots tagged `durability_bypass = true` at
1160/// emission carry no engine state worth replicating before delivery —
1161/// see [`OutputSlot::durability_bypass`] for the correctness argument —
1162/// so clients receive the halt reason immediately rather than blocking
1163/// on a structurally unsatisfiable policy (e.g. `Hybrid` with all
1164/// replicas disconnected, which would otherwise stall the gate until
1165/// peers return). Second, the slot's own event is already durable.
1166///
1167/// Applied per slot rather than per batch, so a bypass slot is released
1168/// as soon as the dispatch loop reaches it instead of riding behind a
1169/// gated slot earlier in the same batch. Ordering is unaffected: the
1170/// loop walks slots in ring order either way, so a bypass slot still
1171/// leaves after everything sequenced before it.
1172///
1173/// Shared by both response stages. The matching stage that sets the flag
1174/// is transport-agnostic, so the same slots reach the io_uring and DPDK
1175/// paths and the two must agree; keeping the predicate in one place is
1176/// what stops them drifting apart again.
1177#[inline]
1178pub(crate) fn slot_needs_gate<R: Copy, Q: Copy>(
1179 slot: &OutputSlot<R, Q>,
1180 cached_durable_pos: u64,
1181) -> bool {
1182 !slot.durability_bypass && cached_durable_pos < slot.wire_seq
1183}
1184
1185/// Tear down a connection the *response stage* decided to drop (send
1186/// error, `MAX_SEND_BUF` overflow, blocked-send timeout).
1187///
1188/// Removing the map entry alone only drops this stage's dup of the
1189/// socket — the reader still holds its own dup, so the socket would
1190/// stay fully open: the dropped client's requests keep flowing through
1191/// the reader (whose idle timeout never fires while the client keeps
1192/// sending) with no response ever delivered, and the accept loop's
1193/// `max_connections` permit stays pinned forever. `shutdown(2)` reaches
1194/// every dup: the reader's multishot RECV completes with 0, it tears
1195/// down its slab entry and emits `Disconnected` — which finds this
1196/// entry already gone, so the permit is released exactly once.
1197fn teardown_dropped(entry: ConnectionEntry, active_connections: &AtomicU64) {
1198 // Best-effort: ENOTCONN just means the peer tore the socket down
1199 // first — dropping `entry` below still reclaims our dup.
1200 unsafe {
1201 libc::shutdown(entry.fd, libc::SHUT_RDWR);
1202 }
1203 active_connections.fetch_sub(1, Ordering::Relaxed);
1204}
1205
1206/// Outcome of a single per-frame append. `Continue` means the
1207/// caller may proceed to the next frame for this slot;
1208/// `ConnectionDropped` means the connection's send buffer overflowed
1209/// or the encode failed, and the connection has been queued for
1210/// removal — no further frames should be appended for this slot.
1211#[derive(Clone, Copy)]
1212enum AppendOutcome {
1213 Continue,
1214 ConnectionDropped,
1215}
1216
1217/// Copy an encoded frame into the connection's send buffer with
1218/// overflow checking. Splits the responsibilities the inline encode
1219/// loop used to have: the caller passes in the encode result (so it
1220/// can come from the `ResponseEncoder` trait for application
1221/// payloads, or `encode_transport_response` for transport-shaped
1222/// frames), and this helper handles size accounting + dirty
1223/// tracking uniformly.
1224/// Whether the idle-path heartbeat scan should append a frame to this
1225/// connection: idle for a full interval — and able to receive it.
1226///
1227/// The two guards close the one append path that used to bypass
1228/// `MAX_SEND_BUF`. A blocked peer's socket is full, so a heartbeat
1229/// would only sit in `send_buf` — and an idle client that trickle-read
1230/// a few bytes per interval kept resetting the blocked clock while
1231/// unchecked heartbeat appends grew its buffer without bound, pinning
1232/// its connection permit on ever-growing memory. Skipping blocked
1233/// peers (they detect liveness by draining, not by new frames) and
1234/// cap-checking the append bounds the buffer; a peer that never drains
1235/// is then `BLOCKED_SEND_TIMEOUT`'s or `MAX_SEND_BUF`'s problem, as
1236/// designed. Residual: a trickling client still holds its permit while
1237/// it drains — bounded memory, and the reader's idle timeout covers
1238/// clients that stop sending entirely.
1239fn heartbeat_due(
1240 entry: &ConnectionEntry,
1241 now: Instant,
1242 interval: Duration,
1243 frame_len: usize,
1244) -> bool {
1245 now.duration_since(entry.last_send) >= interval
1246 && entry.blocked_since.is_none()
1247 && entry.send_buf.len() + frame_len <= MAX_SEND_BUF
1248}
1249
1250#[allow(clippy::too_many_arguments)]
1251fn append_frame(
1252 result: Result<usize, &'static str>,
1253 connection_id: u64,
1254 entry: &mut ConnectionEntry,
1255 encode_buf: &[u8],
1256 batch_now: Instant,
1257 dirty_connections: &mut HashSet<u64>,
1258 to_remove: &mut Vec<u64>,
1259) -> AppendOutcome {
1260 let written = match result {
1261 Ok(n) => n,
1262 Err(reason) => {
1263 tracing::error!(connection_id, reason, "encode error");
1264 return AppendOutcome::Continue;
1265 }
1266 };
1267
1268 // Drop slow clients whose send buffer has grown too large. This
1269 // prevents unbounded memory growth from a single laggy connection
1270 // causing allocator pressure and tail latency spikes.
1271 if entry.send_buf.len() + written > MAX_SEND_BUF {
1272 debug!(
1273 connection_id,
1274 send_buf_len = entry.send_buf.len(),
1275 "send buffer exceeded limit, dropping connection"
1276 );
1277 to_remove.push(connection_id);
1278 return AppendOutcome::ConnectionDropped;
1279 }
1280
1281 // Append the full wire frame to the connection's send buffer.
1282 // The encoder writes [length(4) | payload], which is the complete
1283 // wire format — no extra framing needed.
1284 entry.send_buf.extend_from_slice(&encode_buf[..written]);
1285 entry.last_send = batch_now;
1286 dirty_connections.insert(connection_id);
1287 AppendOutcome::Continue
1288}
1289
1290/// Each dirty connection's accumulated send buffer is sent in a single
1291/// SEND operation, and the flush never blocks on a slow peer.
1292///
1293/// Every SEND carries `MSG_DONTWAIT`, so a full socket buffer completes
1294/// immediately with `EAGAIN` instead of parking the operation until the
1295/// peer reads. That matters because io_uring never surfaces `EAGAIN` for
1296/// a plain SEND — it arms an internal poll and withholds the CQE, which
1297/// is what let one zero-window client wedge this stage (and with it every
1298/// client's acks) behind the `submit_and_wait` below.
1299///
1300/// Undelivered bytes (EAGAIN or a partial send) stay in the connection's
1301/// `send_buf` and the connection stays in `dirty`; retries are paced by
1302/// [`BLOCKED_RETRY_INTERVAL`] and bounded by [`BLOCKED_SEND_TIMEOUT`].
1303/// `MAX_SEND_BUF` remains the growth cap while new responses accumulate.
1304///
1305/// On return, `dirty` holds exactly the connections that still have
1306/// undelivered bytes and were not queued in `to_remove` — callers must
1307/// not clear it. Failed connections are collected in `to_remove` for the
1308/// caller to purge from `connections`.
1309fn flush_sends(
1310 ring: &mut IoUring,
1311 connections: &mut HashMap<u64, ConnectionEntry>,
1312 dirty: &mut HashSet<u64>,
1313 to_remove: &mut Vec<u64>,
1314 cqes: &mut Vec<(u64, i32)>,
1315) {
1316 // One clock read per flush, shared by the retry-pacing and
1317 // blocked-timeout decisions. Cheap next to the submit syscall below,
1318 // and flushes are already batched (one per drained SPSC batch or
1319 // idle-loop pass, not one per response).
1320 let now = Instant::now();
1321
1322 // Submit SEND SQEs for all dirty connections not in retry backoff.
1323 let mut pending: usize = 0;
1324 for &conn_id in dirty.iter() {
1325 let Some(entry) = connections.get_mut(&conn_id) else {
1326 continue;
1327 };
1328 if entry.send_buf.is_empty() {
1329 continue;
1330 }
1331 if let Some(blocked_at) = entry.blocked_since {
1332 // A peer that has refused bytes for the full timeout is not
1333 // coming back for them — reclaim the slot. Client-caused,
1334 // hence debug (see the log-level convention).
1335 if now.duration_since(blocked_at) >= BLOCKED_SEND_TIMEOUT {
1336 debug!(
1337 connection_id = conn_id,
1338 pending_bytes = entry.send_buf.len(),
1339 blocked_ms = now.duration_since(blocked_at).as_millis() as u64,
1340 "socket blocked past timeout, dropping connection"
1341 );
1342 to_remove.push(conn_id);
1343 continue;
1344 }
1345 if now.duration_since(entry.last_send_attempt) < BLOCKED_RETRY_INTERVAL {
1346 continue;
1347 }
1348 }
1349 entry.last_send_attempt = now;
1350
1351 let sqe = opcode::Send::new(
1352 types::Fd(entry.fd),
1353 entry.send_buf.as_ptr(),
1354 entry.send_buf.len() as u32,
1355 )
1356 .flags(libc::MSG_DONTWAIT)
1357 .build()
1358 .user_data(conn_id);
1359
1360 unsafe {
1361 ring.submission()
1362 .push(&sqe)
1363 .expect("io_uring SQ full — increase RING_SIZE");
1364 }
1365 pending += 1;
1366 }
1367
1368 if pending > 0 {
1369 // With MSG_DONTWAIT every SEND completes during submission
1370 // (success, partial, or EAGAIN — the flag sets the kernel's
1371 // no-wait path, so nothing is deferred to a poll retry). The
1372 // wait is bounded by op execution, never by a peer.
1373 //
1374 // EINTR must retry, not return: a signal (profilers use them
1375 // routinely) can interrupt the CQE wait *after* the submit phase
1376 // consumed the SQEs — the inline completions are already posted
1377 // by then. Returning without reaping would leave stale CQEs that
1378 // the next flush drains against *updated* buffer contents:
1379 // a delivered prefix gets re-sent and `drain(..sent)` double-
1380 // drains. The retry submits an empty SQ and finds the CQ already
1381 // holding `pending` entries, so it cannot stall.
1382 loop {
1383 match ring.submit_and_wait(pending) {
1384 Ok(_) => break,
1385 Err(ref e) if e.raw_os_error() == Some(libc::EINTR) => continue,
1386 Err(e) => {
1387 // Submit-phase failure (ENOMEM class — EBUSY cannot
1388 // happen: the CQ is RING_SIZE deep and fully reaped
1389 // every flush, so at most `pending` ≤ RING_SIZE
1390 // entries are ever outstanding). An error here means
1391 // the SQEs were NOT consumed: continuing would leave
1392 // them queued for the next flush's submit, by which
1393 // time their addr fields can point at drained or
1394 // reallocated send_bufs — garbage on client sockets,
1395 // on the ack path. The kernel is out of resources
1396 // and the stage cannot proceed without corruption
1397 // risk: fail loudly and let the accept loop's
1398 // pipeline-death detection take the server down.
1399 error!(error = %e, "io_uring submit_and_wait failed in response stage");
1400 panic!("response stage io_uring submit failed: {e}");
1401 }
1402 }
1403 }
1404
1405 // Drain completions into pre-allocated buffer. Must collect to
1406 // release CQ borrow before mutating connections.
1407 cqes.clear();
1408 cqes.extend(ring.completion().map(|cqe| (cqe.user_data(), cqe.result())));
1409
1410 for &(conn_id, result) in cqes.iter() {
1411 let Some(entry) = connections.get_mut(&conn_id) else {
1412 continue;
1413 };
1414 if result == -libc::EAGAIN {
1415 // Socket buffer full. Keep the bytes; the connection
1416 // stays dirty and retries at the paced cadence.
1417 if entry.blocked_since.is_none() {
1418 entry.blocked_since = Some(now);
1419 }
1420 continue;
1421 }
1422 if result < 0 {
1423 debug!(
1424 connection_id = conn_id,
1425 error = result,
1426 "send error, dropping connection"
1427 );
1428 to_remove.push(conn_id);
1429 continue;
1430 }
1431
1432 let sent = result as usize;
1433 if sent == 0 {
1434 // Unreachable for SOCK_STREAM sends of len > 0 (the
1435 // kernel reports -EAGAIN instead), but keep the
1436 // zero-progress invariant literal: 0 bytes must not
1437 // restart the blocked clock via the partial branch.
1438 if entry.blocked_since.is_none() {
1439 entry.blocked_since = Some(now);
1440 }
1441 } else if sent >= entry.send_buf.len() {
1442 entry.send_buf.clear();
1443 entry.blocked_since = None;
1444 } else {
1445 // Partial send — the socket buffer filled mid-copy. An
1446 // immediate retry would only report EAGAIN, so keep the
1447 // remainder for the paced retry. Bytes moved, though:
1448 // restart the blocked clock from this progress, so only
1449 // a peer accepting *zero* bytes for the full timeout is
1450 // dropped — a slow-but-draining client keeps its
1451 // connection (until `MAX_SEND_BUF` says otherwise).
1452 entry.send_buf.drain(..sent);
1453 entry.blocked_since = Some(now);
1454 }
1455 }
1456 }
1457
1458 // Keep exactly the connections that still hold undelivered bytes and
1459 // survived this flush. Runs even when nothing was submitted so a
1460 // blocked-timeout drop above still leaves the dirty set consistent.
1461 dirty.retain(|conn_id| {
1462 !to_remove.contains(conn_id)
1463 && connections
1464 .get(conn_id)
1465 .is_some_and(|e| !e.send_buf.is_empty())
1466 });
1467}
1468
1469/// Read the live gate cursors and lend them to `f` as a [`CursorView`].
1470///
1471/// The view contains the primary followed by every *currently connected*
1472/// replica slot. Disconnected slots are omitted rather than entered with
1473/// zero cursors, so `CursorView::len` reflects how many nodes are
1474/// actually available to satisfy a clause — too few and the policy
1475/// reports degraded and the gate stalls. Node 0 is always the primary;
1476/// [`Policy::attribute_blocker`] relies on that index convention to tell
1477/// journal from replication.
1478///
1479/// The primary's in-memory cursor is modeled as `u64::MAX` because the
1480/// response stage only gates events the matching engine has already
1481/// processed — those are trivially in-memory on the primary.
1482///
1483/// Scoped-borrow shape rather than a returned view: `CursorView` holds a
1484/// slice, so it cannot outlive the array behind it. Lending it to a
1485/// closure keeps that array on this frame and off every caller's
1486/// signature.
1487#[inline]
1488fn with_cursor_view<R>(
1489 journal_pos: WireSeq,
1490 metrics: Option<&ReplicationMetrics>,
1491 replica_active: Option<&[Arc<AtomicBool>; 2]>,
1492 f: impl FnOnce(&CursorView<'_>) -> R,
1493) -> R {
1494 // Fixed-size array rather than a `Vec`: the cluster is capped at
1495 // MAX_CLUSTER_SIZE and this runs on the gate path, so a heap
1496 // allocation would be pure overhead. Raw `u64` in wire-seq space —
1497 // `journal_pos` leaves the type system here, alongside the replica
1498 // metrics gauges (the `Ack` frame's wire-seq fields verbatim).
1499 let mut nodes = [[0u64; 2]; MAX_CLUSTER_SIZE as usize];
1500 nodes[0] = [u64::MAX, journal_pos.get()];
1501 let mut len = 1;
1502 if let (Some(m), Some(active)) = (metrics, replica_active) {
1503 for (i, slot_active) in active.iter().enumerate() {
1504 // Skip inactive slots up-front.
1505 if !slot_active.load(Ordering::Acquire) {
1506 continue;
1507 }
1508 let in_mem = m.in_memory_sequence[i].load(Ordering::Acquire);
1509 let persisted = m.acked_sequence[i].load(Ordering::Acquire);
1510 nodes[len] = [in_mem, persisted];
1511 len += 1;
1512 }
1513 }
1514 f(&CursorView::new(&nodes[..len]))
1515}
1516
1517/// Highest sequence at which the policy is satisfied by the live
1518/// cursors, plus whether the cluster shape can satisfy it at all.
1519#[inline]
1520pub(crate) fn evaluate_durability(
1521 policy: &Policy,
1522 journal_pos: WireSeq,
1523 metrics: Option<&ReplicationMetrics>,
1524 replica_active: Option<&[Arc<AtomicBool>; 2]>,
1525) -> EvalStatus {
1526 with_cursor_view(journal_pos, metrics, replica_active, |view| {
1527 policy.evaluate_with_status(view)
1528 })
1529}
1530
1531/// One-snapshot gate evaluation: the policy's durable position plus,
1532/// when that position opens the gate (`>= needed`), which subsystem
1533/// supplied the binding cursor.
1534///
1535/// Both answers come from the *same* [`CursorView`]. Re-reading the
1536/// replica cursors for attribution after the evaluation that opened the
1537/// gate would rank a later snapshot — the replica side can advance
1538/// between the two reads and flip the verdict to a subsystem that was
1539/// not the one the gate actually opened on.
1540///
1541/// The blocker is `None` while the gate stays closed (attribution is
1542/// only read at the open, and ranking the clauses for it on every spin
1543/// iteration would be wasted work). At an open with `needed >= 1` it is
1544/// always `Some`: a policy left unsatisfiable by the cluster shape pins
1545/// `durable_pos` to 0, which cannot reach `needed`.
1546///
1547/// The attribution itself replaces the old "compare the journal cursor
1548/// against the minimum replica *persisted* cursor" heuristic, which
1549/// reported replication as the blocker under `local` — where replicas
1550/// cannot bind the gate at all — and read the persisted level under
1551/// `hybrid`, which gates on in-memory.
1552#[inline]
1553pub(crate) fn evaluate_gate(
1554 policy: &Policy,
1555 needed: u64,
1556 journal_pos: WireSeq,
1557 metrics: Option<&ReplicationMetrics>,
1558 replica_active: Option<&[Arc<AtomicBool>; 2]>,
1559) -> (EvalStatus, Option<Blocker>) {
1560 with_cursor_view(journal_pos, metrics, replica_active, |view| {
1561 let status = policy.evaluate_with_status(view);
1562 let blocker = if status.durable_pos >= needed {
1563 policy.attribute_blocker(view)
1564 } else {
1565 None
1566 };
1567 (status, blocker)
1568 })
1569}
1570
1571/// The replica-side cursor the active policy is waiting on, for the
1572/// `tick-to-trade` replica-wait histogram. `None` when no clause is
1573/// replica-supplied (e.g. `local`).
1574#[cfg(feature = "tick-to-trade")]
1575#[inline]
1576pub(crate) fn policy_replica_cursor(
1577 policy: &Policy,
1578 journal_pos: WireSeq,
1579 metrics: Option<&ReplicationMetrics>,
1580 replica_active: Option<&[Arc<AtomicBool>; 2]>,
1581) -> Option<u64> {
1582 with_cursor_view(journal_pos, metrics, replica_active, |view| {
1583 policy.replica_gate_cursor(view)
1584 })
1585}
1586
1587/// Hold-time before a state transition is committed to the log.
1588/// Suppresses log spam when a replica flaps faster than this — only
1589/// transitions that hold for at least this long emit warn/info
1590/// entries. The `/healthz` gauge updates immediately regardless,
1591/// so dashboards and alerts still see real-time state.
1592const DEGRADED_FLAP_HOLD: Duration = Duration::from_secs(1);
1593
1594/// Tracks degradation state across calls and emits warn/info logs
1595/// with sustained-state gating + a periodic heartbeat re-emit.
1596///
1597/// The hot path calls [`Self::tick`] every gate iteration / idle
1598/// poll with the current `degraded` value and the wall clock. The
1599/// logger handles:
1600///
1601/// - Updating the `policy_degraded` health gauge immediately.
1602/// - Suppressing log lines for transitions that don't hold for at
1603/// least [`DEGRADED_FLAP_HOLD`] — a replica flapping at sub-second
1604/// cadence produces no log noise, only a quietly-updating gauge.
1605/// - Emitting a warn at the moment a sustained degraded state
1606/// crosses the hold threshold, plus a periodic re-emit every
1607/// `heartbeat_interval` while it persists.
1608/// - Emitting an info when a sustained healthy state crosses the
1609/// hold threshold (the cluster is back to its target shape and
1610/// stayed there long enough that we trust the recovery).
1611pub(crate) struct DegradationLogger {
1612 /// Last value passed to `tick`; what we'd log about if it stayed
1613 /// at this value past the hold threshold.
1614 pending_state: bool,
1615 /// When `pending_state` first appeared. Reset on every flip.
1616 pending_since: Instant,
1617 /// Whether the current pending state has been logged yet. Only
1618 /// the *first* log per sustained streak crosses; subsequent
1619 /// re-emits while degraded are heartbeat warns.
1620 pending_logged: bool,
1621 /// When the last warn fired. Drives the periodic re-emit while
1622 /// degraded.
1623 last_log: Option<Instant>,
1624 /// Wall clock of the previous accrual. The interval since this
1625 /// instant is attributed to the state observed then (`pending_state`)
1626 /// and accumulated into the `policy_degraded_nanos` counter. Advanced
1627 /// by [`Self::accrue`] — reached on every `tick` (post-gate, idle, and
1628 /// the gate-wait pacing tick) and on `reseed`.
1629 last_tick: Instant,
1630}
1631
1632impl DegradationLogger {
1633 pub(crate) fn new(now: Instant) -> Self {
1634 Self {
1635 pending_state: false,
1636 pending_since: now,
1637 pending_logged: true, // healthy is the assumed initial state; nothing to log
1638 last_log: None,
1639 last_tick: now,
1640 }
1641 }
1642
1643 /// Use when the policy is known to start in a degraded state
1644 /// (e.g. a primary in `hybrid` mode with no replica yet
1645 /// connected). Logs a startup warn immediately and treats the
1646 /// state as already-logged so the next tick doesn't re-emit.
1647 pub(crate) fn new_starting_degraded(now: Instant, policy: &Policy) -> Self {
1648 tracing::warn!(
1649 policy = %policy,
1650 "durability policy starts in degraded mode — fewer connected nodes than the target count"
1651 );
1652 Self {
1653 pending_state: true,
1654 pending_since: now,
1655 pending_logged: true,
1656 last_log: Some(now),
1657 last_tick: now,
1658 }
1659 }
1660
1661 /// Charge the interval `[last_tick, now]` to the degraded-duration
1662 /// counter when `prev_degraded` (the state observed at the previous
1663 /// tick) was degraded, then advance `last_tick`. Drives the
1664 /// `_seconds_total` counter so `rate()` reflects time-in-degraded
1665 /// continuously, even mid-incident, rather than only stepping on
1666 /// recovery. Shared by [`Self::tick`] and [`Self::reseed`] so accrual
1667 /// is never skipped on a logger lifecycle boundary.
1668 #[inline]
1669 fn accrue(&mut self, utilization: &StageUtilization, prev_degraded: bool, now: Instant) {
1670 if prev_degraded {
1671 // `duration_since` saturates to zero when `now < last_tick`;
1672 // `now` is always >= `last_tick` here (single-thread monotonic
1673 // clock), matching the plain `duration_since` used elsewhere
1674 // in this file.
1675 let elapsed = now.duration_since(self.last_tick);
1676 // `as_nanos()` is u128; one inter-tick interval is sub-second
1677 // to a few seconds, far below the u64 nanos ceiling (~584
1678 // years), so the cast can't truncate. See the field doc on
1679 // `StageUtilization::policy_degraded_nanos`.
1680 utilization
1681 .policy_degraded_nanos
1682 .fetch_add(elapsed.as_nanos() as u64, Ordering::Relaxed);
1683 }
1684 self.last_tick = now;
1685 }
1686
1687 /// Flush in-flight degraded accrual up to `now`, then reset to a
1688 /// fresh healthy-start logger. Called on a runtime durability-mode
1689 /// swap, which is a logger lifecycle boundary: without flushing
1690 /// first, the pre-swap degraded interval — on the gate-wait path the
1691 /// entire wedge — would be silently dropped. The new policy's actual
1692 /// degraded state is re-derived by the next `tick`, so the brief
1693 /// swap-to-next-tick window is attributed healthy; that residual is
1694 /// bounded by one tick interval, the counter's inherent granularity.
1695 pub(crate) fn reseed(&mut self, utilization: &StageUtilization, now: Instant) {
1696 let prev_state = self.pending_state;
1697 self.accrue(utilization, prev_state, now);
1698 *self = Self::new(now);
1699 }
1700
1701 /// Update the gauge + emit transition/heartbeat logs as needed.
1702 /// Cheap on the hot path: one atomic store, a few branches, one
1703 /// `Instant::duration_since`.
1704 pub(crate) fn tick(
1705 &mut self,
1706 policy: &Policy,
1707 utilization: &StageUtilization,
1708 degraded_now: bool,
1709 now: Instant,
1710 heartbeat_interval: Duration,
1711 ) {
1712 // Charge the just-elapsed interval to the state observed at the
1713 // *previous* tick. Snapshot it up front, before the flap-hold
1714 // bookkeeping below mutates `pending_state`, so accrual stays
1715 // correct even if that block is later reordered.
1716 let prev_state = self.pending_state;
1717 self.accrue(utilization, prev_state, now);
1718
1719 utilization
1720 .policy_degraded
1721 .store(degraded_now, Ordering::Relaxed);
1722
1723 if degraded_now != self.pending_state {
1724 // State changed — start a new hold window. Don't log
1725 // until / unless this new state stays long enough.
1726 self.pending_state = degraded_now;
1727 self.pending_since = now;
1728 self.pending_logged = false;
1729 return;
1730 }
1731
1732 // State held. If we haven't yet logged this streak's onset,
1733 // and it's been pending for at least the flap-hold time,
1734 // emit the transition message and mark logged.
1735 if !self.pending_logged && now.duration_since(self.pending_since) >= DEGRADED_FLAP_HOLD {
1736 if degraded_now {
1737 tracing::warn!(
1738 policy = %policy,
1739 "durability policy operating in degraded mode — fewer connected nodes than the target count, response gate stalled until the cluster recovers or the mode is swapped"
1740 );
1741 } else {
1742 tracing::info!(
1743 policy = %policy,
1744 "durability policy returned to target shape"
1745 );
1746 }
1747 self.pending_logged = true;
1748 self.last_log = Some(now);
1749 return;
1750 }
1751
1752 // Heartbeat re-emit while a degraded state persists.
1753 if degraded_now
1754 && self.pending_logged
1755 && self
1756 .last_log
1757 .is_none_or(|t| now.duration_since(t) >= heartbeat_interval)
1758 {
1759 tracing::warn!(
1760 policy = %policy,
1761 "durability policy still degraded — fewer connected nodes than the target count"
1762 );
1763 self.last_log = Some(now);
1764 }
1765 }
1766}
1767
1768/// Tracks per-cursor "first observed transition from below to >= needed"
1769/// inside the durability gate loop, to drive the journal-wait /
1770/// replica-wait histograms in the bench's tick-to-trade decomposition.
1771///
1772/// A sample is recorded only for cursors that were strictly below
1773/// `needed` at the loop's first observation. Cursors already past at
1774/// entry were not on the critical path for this batch, so attributing
1775/// "wait time" to them would inflate the metric with cursor-poll
1776/// observation timestamps that have nothing to do with how long the
1777/// stage actually held us up.
1778///
1779/// `now_ns` is taken as a parameter rather than read internally so
1780/// tests can supply deterministic timestamps. The caller's hot path
1781/// reads `trace::mono_trace_ns()` once per gate iteration and feeds it in.
1782#[cfg(feature = "tick-to-trade")]
1783pub(crate) struct GateCrossTracker {
1784 needed: u64,
1785 journal_crossed_ts: Option<trace::MonoTraceInstant>,
1786 replica_crossed_ts: Option<trace::MonoTraceInstant>,
1787 journal_was_below: bool,
1788 replica_was_below: bool,
1789 first: bool,
1790}
1791
1792#[cfg(feature = "tick-to-trade")]
1793impl GateCrossTracker {
1794 pub(crate) fn new(needed: u64) -> Self {
1795 Self {
1796 needed,
1797 journal_crossed_ts: None,
1798 replica_crossed_ts: None,
1799 journal_was_below: false,
1800 replica_was_below: false,
1801 first: true,
1802 }
1803 }
1804
1805 /// `replica_pos` is the replica-side cursor the *active policy*
1806 /// gates on — see [`policy_replica_cursor`]. `None` means no replica
1807 /// currently supplies a binding cursor, which happens permanently
1808 /// under `local` and transiently when the binding replica drops out
1809 /// of the cursor view part-way through a wait.
1810 ///
1811 /// Both cases must leave `replica_crossed_ts` alone. Treating
1812 /// `None` as an infinite cursor would satisfy the crossing test and
1813 /// latch the timestamp at the *disconnect*, reporting a replica
1814 /// wait that ended when the link died rather than when the replica
1815 /// caught up — understating exactly the failover runs the histogram
1816 /// exists to measure. On the first observe it additionally leaves
1817 /// `replica_was_below` false, so a policy that never waits on a
1818 /// replica records no sample at all.
1819 pub(crate) fn observe(
1820 &mut self,
1821 journal_pos: u64,
1822 replica_pos: Option<u64>,
1823 now_ns: trace::MonoTraceInstant,
1824 ) {
1825 if self.first {
1826 self.journal_was_below = journal_pos < self.needed;
1827 self.replica_was_below = replica_pos.is_some_and(|p| p < self.needed);
1828 self.first = false;
1829 }
1830 if self.journal_was_below && self.journal_crossed_ts.is_none() && journal_pos >= self.needed
1831 {
1832 self.journal_crossed_ts = Some(now_ns);
1833 }
1834 if self.replica_was_below
1835 && self.replica_crossed_ts.is_none()
1836 && replica_pos.is_some_and(|p| p >= self.needed)
1837 {
1838 self.replica_crossed_ts = Some(now_ns);
1839 }
1840 }
1841
1842 pub(crate) fn journal_crossed(&self) -> Option<trace::MonoTraceInstant> {
1843 self.journal_crossed_ts
1844 }
1845
1846 pub(crate) fn replica_crossed(&self) -> Option<trace::MonoTraceInstant> {
1847 self.replica_crossed_ts
1848 }
1849}
1850
1851/// Print busy/idle utilization for a pipeline stage on shutdown.
1852#[cfg(feature = "pipeline-stats")]
1853fn print_utilization(stage: &str, busy: u64, idle: u64) {
1854 let total = busy + idle;
1855 if total == 0 {
1856 tracing::info!(stage, "no iterations recorded");
1857 return;
1858 }
1859 let pct = (busy as f64 / total as f64) * 100.0;
1860 tracing::info!(
1861 stage,
1862 pct_busy = format_args!("{pct:.2}%"),
1863 busy,
1864 idle,
1865 total,
1866 "pipeline utilization",
1867 );
1868}
1869
1870#[cfg(test)]
1871mod tests {
1872 #[cfg(feature = "tick-to-trade")]
1873 use super::GateCrossTracker;
1874 use super::{
1875 Blocker, DegradationLogger, OutputSlot, WireSeq, evaluate_durability, evaluate_gate,
1876 slot_needs_gate,
1877 };
1878 use crate::durability_policy::{Clause, Level, Policy};
1879 use crate::replication::ReplicationMetrics;
1880
1881 /// Queued end-to-end samples survive a flush that dropped nothing,
1882 /// and are closed (drained) by it.
1883 #[cfg(feature = "latency-trace")]
1884 #[test]
1885 fn e2e_samples_survive_until_a_flush_closes_them() {
1886 let mut pending = vec![(1u64, 10u64), (2, 20), (1, 30)];
1887 super::discard_e2e_samples(&mut pending, &[]);
1888 assert_eq!(pending.len(), 3, "an empty drop list must lose nothing");
1889
1890 let mut rec = melin_transport_core::trace::register_stage("test::response_e2e_close");
1891 super::close_e2e_samples(&mut pending, &mut rec);
1892 assert!(pending.is_empty(), "a flush closes the whole queue");
1893 }
1894
1895 /// The defect this pairing exists to prevent: a dropped connection's
1896 /// buffered bytes are discarded with it, so its samples must not
1897 /// survive to be timed against some later connection's flush.
1898 #[cfg(feature = "latency-trace")]
1899 #[test]
1900 fn e2e_samples_for_a_dropped_connection_are_discarded() {
1901 let mut pending = vec![(1u64, 10u64), (2, 20), (1, 30), (3, 40)];
1902 super::discard_e2e_samples(&mut pending, &[1, 3]);
1903 assert_eq!(
1904 pending,
1905 vec![(2, 20)],
1906 "only the surviving connection's samples remain"
1907 );
1908
1909 // Dropping the last live connection empties the queue, which is
1910 // what restores "queue non-empty implies something is dirty" —
1911 // the invariant the flush sites rely on to be sufficient drain
1912 // points.
1913 super::discard_e2e_samples(&mut pending, &[2]);
1914 assert!(pending.is_empty());
1915 }
1916
1917 /// Output slot carrying only the fields the gate decision reads.
1918 /// `()` for the report/query types keeps the fixture independent of
1919 /// any concrete application.
1920 fn slot(wire_seq: u64, durability_bypass: bool) -> OutputSlot<(), ()> {
1921 OutputSlot {
1922 wire_seq,
1923 durability_bypass,
1924 ..Default::default()
1925 }
1926 }
1927
1928 #[test]
1929 fn bypass_slot_never_gates() {
1930 // Halt-state output must not block on a policy that may be
1931 // structurally unsatisfiable, however far behind the cursor is.
1932 assert!(!slot_needs_gate(&slot(10, true), 0));
1933 assert!(!slot_needs_gate(&slot(10, true), 9));
1934 }
1935
1936 #[test]
1937 fn normal_slot_gates_until_its_own_sequence_is_durable() {
1938 assert!(slot_needs_gate(&slot(10, false), 0));
1939 assert!(slot_needs_gate(&slot(10, false), 9));
1940 }
1941
1942 #[test]
1943 fn normal_slot_clears_at_its_own_sequence_not_the_batch_maximum() {
1944 // The cursor reaching exactly this slot's `wire_seq` is enough —
1945 // an off-by-one here would stall every response an extra
1946 // durability round-trip. A later slot in the same batch needing
1947 // more must not hold this one back.
1948 assert!(!slot_needs_gate(&slot(10, false), 10));
1949 assert!(!slot_needs_gate(&slot(10, false), 11));
1950 }
1951
1952 /// Build a [`Policy`] from a mini DSL: one or more
1953 /// `"<level>>=<count>"` clauses joined with `&&`. Test-only
1954 /// ergonomics — production builds policies via
1955 /// [`DurabilityMode::to_policy`].
1956 fn parse(s: &str) -> Result<Policy, String> {
1957 let mut clauses = Vec::new();
1958 for raw in s.split("&&") {
1959 let token = raw.trim();
1960 let (lvl, rhs) = token
1961 .split_once(">=")
1962 .ok_or_else(|| format!("clause `{token}` missing `>=`"))?;
1963 let level = match lvl.trim() {
1964 "persisted" => Level::Persisted,
1965 "in_memory" => Level::InMemory,
1966 other => return Err(format!("unknown level `{other}`")),
1967 };
1968 let count: u8 = rhs.trim().parse().map_err(|e| format!("bad count: {e}"))?;
1969 clauses.push(Clause { count, level });
1970 }
1971 Policy::new(clauses).map_err(|e| e.to_string())
1972 }
1973 use melin_transport_core::pipeline::StageUtilization;
1974 use std::sync::Arc;
1975 use std::sync::atomic::{AtomicBool, Ordering};
1976 use std::time::{Duration, Instant};
1977
1978 /// Build a `ReplicationMetrics` with both slots populated. Tests
1979 /// that need to simulate a disconnected slot use [`flags`] to mark
1980 /// it inactive — its cursors are then ignored regardless of value.
1981 fn metrics(slot0: (u64, u64), slot1: (u64, u64)) -> Arc<ReplicationMetrics> {
1982 let m = Arc::new(ReplicationMetrics::default());
1983 m.in_memory_sequence[0].store(slot0.0, Ordering::Relaxed);
1984 m.acked_sequence[0].store(slot0.1, Ordering::Relaxed);
1985 m.in_memory_sequence[1].store(slot1.0, Ordering::Relaxed);
1986 m.acked_sequence[1].store(slot1.1, Ordering::Relaxed);
1987 m
1988 }
1989
1990 /// Build a `[active; 2]` flags array.
1991 fn flags(slot0_active: bool, slot1_active: bool) -> [Arc<AtomicBool>; 2] {
1992 [
1993 Arc::new(AtomicBool::new(slot0_active)),
1994 Arc::new(AtomicBool::new(slot1_active)),
1995 ]
1996 }
1997
1998 /// Both replicas active — the common healthy-cluster case.
1999 fn both_active() -> [Arc<AtomicBool>; 2] {
2000 flags(true, true)
2001 }
2002
2003 // --- Standalone (no replicas wired) ---
2004
2005 #[test]
2006 fn standalone_persisted_one_gates_on_journal() {
2007 // No metrics → only the primary is in the view. `persisted>=1`
2008 // is satisfied by the primary alone at journal_pos.
2009 let p = parse("persisted>=1").unwrap();
2010 assert_eq!(
2011 evaluate_durability(&p, WireSeq::new(500), None, None).durable_pos,
2012 500
2013 );
2014 }
2015
2016 #[test]
2017 fn standalone_strict_persisted_two_never_opens() {
2018 // `persisted>=2` on a standalone primary stays at 0: the
2019 // operator asked for two copies and there is only one. The
2020 // policy surfaces as degraded so the operator sees the gate
2021 // is stalled because the cluster can't meet the policy.
2022 let p = parse("persisted>=2").unwrap();
2023 let r = evaluate_durability(&p, WireSeq::new(500), None, None);
2024 assert_eq!(r.durable_pos, 0);
2025 assert!(
2026 r.degraded,
2027 "policy structurally unsatisfiable on this shape → degraded",
2028 );
2029 }
2030
2031 // --- 2 replicas connected ---
2032
2033 #[test]
2034 fn quorum_both_replicas_ahead_of_journal() {
2035 // Both replicas persisted past journal. `persisted>=2` returns
2036 // the 2nd-largest persisted across {primary, slot0, slot1}.
2037 let p = parse("persisted>=2").unwrap();
2038 let m = metrics((100, 100), (120, 120));
2039 let a = both_active();
2040 assert_eq!(
2041 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
2042 100
2043 );
2044 }
2045
2046 #[test]
2047 fn quorum_journal_ahead_of_both_replicas() {
2048 // Journal at 500, replicas at 100/120. 2nd-largest persisted = 120.
2049 let p = parse("persisted>=2").unwrap();
2050 let m = metrics((100, 100), (120, 120));
2051 let a = both_active();
2052 assert_eq!(
2053 evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a)).durable_pos,
2054 120
2055 );
2056 }
2057
2058 #[test]
2059 fn quorum_journal_between_slow_and_fast_replica() {
2060 // {primary=150, slot0_persisted=50, slot1_persisted=200}.
2061 // 2nd-largest = 150 (primary itself).
2062 let p = parse("persisted>=2").unwrap();
2063 let m = metrics((50, 50), (200, 200));
2064 let a = both_active();
2065 assert_eq!(
2066 evaluate_durability(&p, WireSeq::new(150), Some(&m), Some(&a)).durable_pos,
2067 150
2068 );
2069 }
2070
2071 // --- Single replica connected ---
2072
2073 #[test]
2074 fn single_replica_strict_persisted_two_requires_both_survivors() {
2075 // Slot 0 connected, slot 1 disconnected. View = {primary, slot0}.
2076 // Strict `persisted>=2`: 2nd-largest of the 2-row view =
2077 // min(primary, slot0). Strictly stronger than legacy auto-
2078 // degrade-to-1-node in the same shape.
2079 let p = parse("persisted>=2").unwrap();
2080 let m = metrics((100, 100), (999, 999)); // slot 1 cursors ignored
2081 let a = flags(true, false);
2082 assert_eq!(
2083 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
2084 50
2085 );
2086 assert_eq!(
2087 evaluate_durability(&p, WireSeq::new(200), Some(&m), Some(&a)).durable_pos,
2088 100
2089 );
2090 }
2091
2092 #[test]
2093 fn single_replica_persisted_two_requires_both_survivors() {
2094 // 2-node view (primary + surviving replica). `persisted>=2` is
2095 // satisfiable; the gate opens at the slower of the two and the
2096 // policy is not degraded.
2097 let p = parse("persisted>=2").unwrap();
2098 let m = metrics((100, 100), (999, 999));
2099 let a = flags(true, false);
2100 let r = evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a));
2101 assert_eq!(r.durable_pos, 50);
2102 assert!(!r.degraded);
2103 }
2104
2105 #[test]
2106 fn both_replicas_disconnected_strict_stalls() {
2107 // View has only the primary. Strict `persisted>=2` cannot be
2108 // satisfied — operator opted out of degrade.
2109 let p = parse("persisted>=2").unwrap();
2110 let m = metrics((999, 999), (999, 999));
2111 let a = flags(false, false);
2112 assert_eq!(
2113 evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a)).durable_pos,
2114 0
2115 );
2116 }
2117
2118 #[test]
2119 fn both_replicas_disconnected_strict_stalls_and_flags_degraded() {
2120 // With `persisted>=2` and both replicas down, the cursor view
2121 // collapses to {primary}: the clause's count (=2) exceeds the
2122 // view size, so the gate stays at 0 and the policy flags
2123 // degraded. Note the matching stage's separate halt at
2124 // `replicas_connected==0` rejects new orders before they reach
2125 // the gate; this verifies the gate semantics in isolation.
2126 let p = parse("persisted>=2").unwrap();
2127 let m = metrics((999, 999), (999, 999));
2128 let a = flags(false, false);
2129 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
2130 assert_eq!(r.durable_pos, 0);
2131 assert!(r.degraded);
2132 }
2133
2134 // --- Mixed-level policies ---
2135
2136 #[test]
2137 fn persisted_one_and_in_memory_two() {
2138 // "Leader persists, plus one other node has it in memory" —
2139 // the cheap-but-non-zero durability target. Slot 0 has it in
2140 // memory, slot 1 disconnected.
2141 let p = parse("persisted>=1 && in_memory>=2").unwrap();
2142 // primary persisted=50, slot0 in_mem=80 / persisted=20.
2143 // persisted>=1: max(50, 20, 0) = 50.
2144 // in_memory>=2: primary in_mem=u64::MAX (always), slot0_eff=max(80, 20)=80,
2145 // slot1=0. 2nd-largest = 80.
2146 // min(50, 80) = 50.
2147 let m = metrics((80, 20), (999, 999));
2148 let a = flags(true, false);
2149 assert_eq!(
2150 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
2151 50
2152 );
2153 }
2154
2155 // --- Edge: journal at 0 ---
2156
2157 #[test]
2158 fn journal_at_zero_with_replicas_persisted_one() {
2159 // Journal hasn't fsynced anything; both replicas have. With
2160 // `persisted>=1` the gate opens at the fastest replica.
2161 let p = parse("persisted>=1").unwrap();
2162 let m = metrics((100, 100), (200, 200));
2163 let a = both_active();
2164 assert_eq!(
2165 evaluate_durability(&p, WireSeq::new(0), Some(&m), Some(&a)).durable_pos,
2166 200
2167 );
2168 }
2169
2170 // --- gate-blocker attribution ---
2171 //
2172 // The attribution must follow the policy actually in force. The
2173 // previous heuristic compared the journal cursor against the
2174 // minimum replica *persisted* cursor unconditionally, which
2175 // reported replication as the blocker under `local` (where
2176 // replicas cannot bind the gate) and read the wrong level under
2177 // `hybrid` (which gates replicas on in-memory).
2178 //
2179 // Attribution comes out of `evaluate_gate` alongside the durable
2180 // position, computed from the same cursor snapshot, and is `None`
2181 // while the gate stays closed — so each test passes a `needed` at
2182 // or below the scenario's durable position to model the iteration
2183 // on which the gate opens.
2184
2185 #[test]
2186 fn local_mode_never_blames_replication() {
2187 // `persisted>=1` is satisfied by the highest persisted cursor
2188 // in the cluster — the primary's. A connected replica lagging
2189 // far behind is irrelevant to the gate, so it must not be
2190 // credited as the blocker. This is the case the old heuristic
2191 // got flatly wrong: journal_pos (500) > repl_min (10) sent it
2192 // down the `else` branch every single time.
2193 let p = parse("persisted>=1").unwrap();
2194 let m = metrics((10, 10), (10, 10));
2195 let a = both_active();
2196 assert_eq!(
2197 evaluate_gate(&p, 500, WireSeq::new(500), Some(&m), Some(&a)).1,
2198 Some(Blocker::Journal)
2199 );
2200 }
2201
2202 #[test]
2203 fn hybrid_reads_replica_in_memory_not_persisted() {
2204 // `persisted>=1 && in_memory>=2`. The replica has the event in
2205 // memory (400) well ahead of its own fsync (100), and the
2206 // primary's journal is behind that in-memory cursor (300).
2207 // The binding clause is therefore the primary's persisted
2208 // cursor → journal. Comparing against the replica's *persisted*
2209 // cursor (100) would have said replication.
2210 let p = parse("persisted>=1 && in_memory>=2").unwrap();
2211 let m = metrics((400, 100), (0, 0));
2212 let a = flags(true, false);
2213 assert_eq!(
2214 evaluate_gate(&p, 300, WireSeq::new(300), Some(&m), Some(&a)).1,
2215 Some(Blocker::Journal)
2216 );
2217
2218 // Same policy, replica in-memory now the laggard → replication.
2219 // The gate opens at the replica's in-memory cursor (200).
2220 let m = metrics((200, 100), (0, 0));
2221 assert_eq!(
2222 evaluate_gate(&p, 200, WireSeq::new(300), Some(&m), Some(&a)).1,
2223 Some(Blocker::Replication)
2224 );
2225 }
2226
2227 #[test]
2228 fn hybrid_is_satisfied_by_the_faster_replica() {
2229 // `in_memory>=2` needs the primary plus *one* replica, so the
2230 // best replica binds, not the worst. Replica 0 holds the event
2231 // in memory at 400 with its own fsync trailing at 250 (behind
2232 // the primary, as the physical ordering requires); replica 1
2233 // lags badly at 10. The gate is not held up by replication —
2234 // the primary's persisted cursor (300) is the binding term.
2235 // Taking the min across replicas would have blamed the slow
2236 // slot.
2237 let p = parse("persisted>=1 && in_memory>=2").unwrap();
2238 let m = metrics((400, 250), (10, 10));
2239 let a = both_active();
2240 assert_eq!(
2241 evaluate_gate(&p, 300, WireSeq::new(300), Some(&m), Some(&a)).1,
2242 Some(Blocker::Journal)
2243 );
2244 }
2245
2246 #[test]
2247 fn durably_replicated_uses_second_largest_persisted() {
2248 // `persisted>=2` is met by the primary plus the *best* replica's
2249 // persisted cursor. With the primary ahead at 900 and replicas
2250 // at 400 and 10, the clause resolves at 400 — the fast replica —
2251 // not at the minimum of 10.
2252 let p = parse("persisted>=2").unwrap();
2253 let m = metrics((400, 400), (10, 10));
2254 let a = both_active();
2255 assert_eq!(
2256 evaluate_durability(&p, WireSeq::new(900), Some(&m), Some(&a)).durable_pos,
2257 400,
2258 "clause takes the second-largest persisted cursor, not the minimum"
2259 );
2260 // Replication binds, which is the norm for this mode: the
2261 // primary persists before it ships, so it is normally ahead of
2262 // every replica.
2263 assert_eq!(
2264 evaluate_gate(&p, 400, WireSeq::new(900), Some(&m), Some(&a)).1,
2265 Some(Blocker::Replication)
2266 );
2267 }
2268
2269 #[test]
2270 fn standalone_credits_the_journal() {
2271 // No replication wired: the primary is the only node, so the
2272 // journal is the only thing the gate can be waiting on.
2273 let p = parse("persisted>=1").unwrap();
2274 assert_eq!(
2275 evaluate_gate(&p, 500, WireSeq::new(500), None, None).1,
2276 Some(Blocker::Journal)
2277 );
2278 }
2279
2280 #[test]
2281 fn unsatisfiable_shape_never_opens_so_never_attributes() {
2282 // `persisted>=2` with no replica connected: the shape pins
2283 // `durable_pos` to 0, so the gate cannot open and no blocker is
2284 // ever produced — the stall is a missing node, not either
2285 // subsystem's progress. `policy_degraded` is the metric for it.
2286 let p = parse("persisted>=2").unwrap();
2287 let (status, blocker) = evaluate_gate(&p, 1, WireSeq::new(500), None, None);
2288 assert!(status.degraded);
2289 assert_eq!(status.durable_pos, 0);
2290 assert_eq!(blocker, None);
2291 }
2292
2293 #[test]
2294 fn closed_gate_yields_no_attribution() {
2295 // The policy is satisfiable and healthy, but the batch needs a
2296 // sequence the cursors haven't reached — the gate stays closed
2297 // and `evaluate_gate` must not spend a ranking pass (nor name a
2298 // blocker) on an iteration that keeps spinning.
2299 let p = parse("persisted>=1").unwrap();
2300 let (status, blocker) = evaluate_gate(&p, 501, WireSeq::new(500), None, None);
2301 assert!(!status.degraded);
2302 assert_eq!(status.durable_pos, 500);
2303 assert_eq!(blocker, None);
2304 }
2305
2306 #[test]
2307 fn attribution_skips_disconnected_slots() {
2308 // Slot 1 is disconnected, so its (very advanced) cursors must
2309 // not satisfy `in_memory>=2`; only slot 0 counts, and it lags.
2310 // The gate opens at slot 0's in-memory cursor (100).
2311 let p = parse("persisted>=1 && in_memory>=2").unwrap();
2312 let m = metrics((100, 100), (999, 999));
2313 let a = flags(true, false);
2314 assert_eq!(
2315 evaluate_gate(&p, 100, WireSeq::new(500), Some(&m), Some(&a)).1,
2316 Some(Blocker::Replication)
2317 );
2318 }
2319
2320 /// Fresh-cluster catch-up: a replica that handshakes at sequence
2321 /// 0 (the legitimate genesis case, not a stale-flag race) must be
2322 /// included in the cursor view with its zero cursors so the policy
2323 /// behaves the same way it would for a 1-replica deployment that
2324 /// has just produced its first batch. The disconnect-race
2325 /// mitigations (B1 seed-on-connect + B2 reorder) keep this from
2326 /// being conflated with the stale-flag-paired-with-zero-cursor
2327 /// case under normal cluster lifecycles.
2328 #[test]
2329 fn fresh_cluster_zero_cursors_included_in_view() {
2330 let p = parse("persisted>=2").unwrap();
2331 // Both replicas just handshook at seq 0, primary also at 0
2332 // (fresh cluster, no events yet). View = 3 nodes; the clause's
2333 // count (=2) is met by the view size, so the policy is not
2334 // degraded and the gate sits at the 2nd-largest persisted = 0.
2335 let m = metrics((0, 0), (0, 0));
2336 let a = both_active();
2337 let r = evaluate_durability(&p, WireSeq::new(0), Some(&m), Some(&a));
2338 assert_eq!(r.durable_pos, 0);
2339 assert!(
2340 !r.degraded,
2341 "all 3 nodes present, view meets clause target — should not flag degraded"
2342 );
2343 }
2344
2345 // -- Race-window regression tests --
2346 //
2347 // The replication senders fix two memory-ordering issues at the
2348 // active-flag transition points:
2349 //
2350 // B1 (`a84540a`): seed `metrics.{acked,in_memory}_sequence[i]`
2351 // to `handshake.last_sequence` BEFORE setting active_flag=true
2352 // on reconnect. Without this, the gate would observe (active=
2353 // true, cursor=0) for ~1 RTT after a replica catch-up completed,
2354 // pinning any multi-node clause — and thus the gate — to 0.
2355 //
2356 // B2 (`8888732`): zero `metrics.{acked,in_memory}_sequence[i]`
2357 // BEFORE setting active_flag=false on disconnect. Without this,
2358 // a weak-memory reader could observe (active=true, cursor=0)
2359 // for one iteration during the disconnect window.
2360 //
2361 // Both fixes are in the senders, but the gate's *behaviour* under
2362 // the race-window inputs is tested here. The intent is to lock in
2363 // the invariant: even under a hypothetical (active=true,cursor=0)
2364 // observation, the gate must not produce a spuriously-open answer
2365 // that would cause a client to be told "your event is durable"
2366 // when it isn't. Stalling-briefly is safe; opening-spuriously is
2367 // not.
2368
2369 #[test]
2370 fn race_b1_post_seed_gate_doesnt_freeze_on_reconnect() {
2371 // Post-B1-fix state: replica reconnected, cursors seeded to
2372 // `handshake.last_sequence` (480) before active flipped to
2373 // true. Primary kept moving and is at 500. The gate's view
2374 // is now [primary=500, slot=480]; the durable position dips
2375 // from 500 (primary alone, degraded) to 480 (both nodes).
2376 //
2377 // The dip is correct, not a bug: once a 2nd node is
2378 // connected, durability is bounded by the slower of the two.
2379 // Events 481-500 were already served as durable on primary
2380 // alone — they aren't unsent. New responses for seq>500 wait
2381 // until slot acks; we just don't freeze at 0.
2382 let p = parse("persisted>=2").unwrap();
2383 let m = metrics((480, 480), (999, 999));
2384 let a = flags(true, false);
2385 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
2386 assert_eq!(
2387 r.durable_pos, 480,
2388 "post-seed reconnect should produce a coherent gate position equal to the slower node, not freeze at 0"
2389 );
2390 }
2391
2392 #[test]
2393 fn race_b1_pre_seed_freeze_is_what_the_fix_avoids() {
2394 // Pre-B1-fix state: cursors at 0, active=true. The gate sees
2395 // [primary=500, slot=[0,0]] and 2nd-largest persisted = 0.
2396 // The gate WOULD freeze at 0. This test documents the bug
2397 // the seeding fix is designed to avoid; the senders ensure
2398 // this state is never observed in production.
2399 let p = parse("persisted>=2").unwrap();
2400 let m = metrics((0, 0), (999, 999));
2401 let a = flags(true, false);
2402 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
2403 assert_eq!(
2404 r.durable_pos, 0,
2405 "the gate behaviour under (active=true, cursor=0) — if the senders ever fail to seed before flipping active, this is the freeze the operator would see"
2406 );
2407 }
2408
2409 #[test]
2410 fn race_b2_disconnect_window_doesnt_open_gate_spuriously() {
2411 // Simulates the B2 race window: a weak-memory reader observes
2412 // (active=true, cursor=0) for one iteration during the
2413 // disconnect transition. The slot legitimately has cursor=0
2414 // because the disconnect handler just zeroed the metrics.
2415 //
2416 // Critical invariant: the gate must NOT produce a higher
2417 // durable_pos than it would with the slot correctly excluded.
2418 // Specifically: with primary at 500, slot stale-zero-included,
2419 // the gate must not "see" the primary alone and open at 500
2420 // — that would let a client be told a seq is durable when
2421 // only the primary has it under a `persisted>=2` policy that
2422 // demands 2 nodes.
2423 let p = parse("persisted>=2").unwrap();
2424 let m = metrics((0, 0), (999, 999));
2425 let a = flags(true, false);
2426 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
2427 // 2nd-largest persisted across {primary=500, slot=0} = 0.
2428 // Gate stalls. ✓
2429 assert_eq!(r.durable_pos, 0);
2430
2431 // Post-disconnect (active=false): view shrinks to {primary}.
2432 // `persisted>=2` is structurally unsatisfiable on a 1-node
2433 // view, so the gate stays at 0 AND surfaces degraded. The
2434 // matching stage's `replicas_connected==0` halt is what stops
2435 // accepting new orders; the gate side's job is just to keep
2436 // the existing in-flight orders stalled and the alert lit.
2437 let a_disconnected = flags(false, false);
2438 let r_after = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a_disconnected));
2439 assert_eq!(r_after.durable_pos, 0);
2440 assert!(
2441 r_after.degraded,
2442 "post-disconnect view of size 1 cannot meet persisted>=2 → degraded"
2443 );
2444 }
2445
2446 #[test]
2447 fn race_invariant_zero_cursor_never_opens_gate_above_slower_node() {
2448 // Property under both B1 and B2 race windows: for any slot
2449 // observed at cursor=0 with active=true, the gate cannot
2450 // produce a durable_pos that exceeds what an honest 2-node
2451 // evaluation would give. Spot-check a handful of primary
2452 // positions to lock the invariant.
2453 let p = parse("persisted>=2").unwrap();
2454 let m = metrics((0, 0), (999, 999));
2455 let a = flags(true, false);
2456 for primary_pos in [0, 1, 100, 500, 1_000_000_000_u64] {
2457 let r = evaluate_durability(&p, WireSeq::new(primary_pos), Some(&m), Some(&a));
2458 // 2nd-largest of {primary_pos, 0} = 0 for any primary > 0.
2459 // For primary_pos = 0, also 0. So always 0.
2460 assert_eq!(
2461 r.durable_pos, 0,
2462 "race-window observation must not open the gate above 0 for any primary position (got {} for primary_pos={primary_pos})",
2463 r.durable_pos
2464 );
2465 }
2466 }
2467
2468 // ------------------------------------------------------------------
2469 // GateCrossTracker — per-cursor "first transition from below to
2470 // crossed" inside the gate loop, used by the journal-wait /
2471 // replica-wait histograms.
2472 // ------------------------------------------------------------------
2473
2474 #[cfg(feature = "tick-to-trade")]
2475 #[test]
2476 fn gate_cross_tracker_records_journal_when_strictly_below() {
2477 // Journal starts at 5 (< 10), repl_min already at 100.
2478 // Journal crosses on the second observation. Replica was already
2479 // past at entry, so no replica sample.
2480 let mut t = GateCrossTracker::new(10);
2481 t.observe(5, Some(100), 1_000);
2482 t.observe(15, Some(100), 2_000);
2483 assert_eq!(t.journal_crossed(), Some(2_000));
2484 assert_eq!(t.replica_crossed(), None);
2485 }
2486
2487 #[cfg(feature = "tick-to-trade")]
2488 #[test]
2489 fn gate_cross_tracker_records_replica_when_strictly_below() {
2490 // Mirror image: journal already past, replica below at entry.
2491 let mut t = GateCrossTracker::new(10);
2492 t.observe(50, Some(5), 1_000);
2493 t.observe(50, Some(12), 2_000);
2494 assert_eq!(t.journal_crossed(), None);
2495 assert_eq!(t.replica_crossed(), Some(2_000));
2496 }
2497
2498 #[cfg(feature = "tick-to-trade")]
2499 #[test]
2500 fn gate_cross_tracker_records_both_when_both_below() {
2501 // Both below at entry, both cross independently.
2502 let mut t = GateCrossTracker::new(100);
2503 t.observe(50, Some(60), 1_000); // both below
2504 t.observe(105, Some(60), 2_000); // journal crosses
2505 t.observe(105, Some(110), 3_000); // replica crosses
2506 assert_eq!(t.journal_crossed(), Some(2_000));
2507 assert_eq!(t.replica_crossed(), Some(3_000));
2508 }
2509
2510 #[cfg(feature = "tick-to-trade")]
2511 #[test]
2512 fn gate_cross_tracker_skips_cursor_already_past_at_entry() {
2513 // Both cursors already >= needed at first observation —
2514 // neither was on the critical path. No samples.
2515 let mut t = GateCrossTracker::new(10);
2516 t.observe(50, Some(100), 1_000);
2517 // Even later observations don't backfill: was_below is sticky.
2518 t.observe(60, Some(110), 2_000);
2519 assert_eq!(t.journal_crossed(), None);
2520 assert_eq!(t.replica_crossed(), None);
2521 }
2522
2523 #[cfg(feature = "tick-to-trade")]
2524 #[test]
2525 fn gate_cross_tracker_first_observation_only_for_cross_decision() {
2526 // A cursor that goes back below `needed` after first iteration
2527 // (impossible in practice — cursors are monotonic — but we
2528 // verify the first-iteration snapshot is what gates the
2529 // sample). Journal: 50 < 10 false → was_below=false → no sample.
2530 let mut t = GateCrossTracker::new(10);
2531 t.observe(50, Some(5), 1_000); // journal already past, replica below
2532 t.observe(20, Some(12), 2_000); // both >= needed now
2533 // Journal: was_below=false at entry → still no sample.
2534 assert_eq!(t.journal_crossed(), None);
2535 // Replica: was_below=true at entry, crosses on iter 2 → sample.
2536 assert_eq!(t.replica_crossed(), Some(2_000));
2537 }
2538
2539 #[cfg(feature = "tick-to-trade")]
2540 #[test]
2541 fn gate_cross_tracker_holds_first_cross_only() {
2542 // Once a cross is recorded, later observations don't
2543 // overwrite — the metric is "when did it first cross", not
2544 // "when was it last below".
2545 let mut t = GateCrossTracker::new(10);
2546 t.observe(5, Some(100), 1_000);
2547 t.observe(15, Some(100), 2_000); // first cross
2548 t.observe(25, Some(100), 3_000); // would otherwise re-record
2549 assert_eq!(t.journal_crossed(), Some(2_000));
2550 }
2551
2552 #[cfg(feature = "tick-to-trade")]
2553 #[test]
2554 fn gate_cross_tracker_ignores_replica_dropping_out_mid_wait() {
2555 // The regression this signature exists for. The replica is
2556 // behind at entry (was_below latches true), then disconnects
2557 // part-way through the wait so no replica supplies a binding
2558 // cursor. That must not be read as "caught up" — the histogram
2559 // would otherwise report a wait that ended at the disconnect.
2560 let mut t = GateCrossTracker::new(100);
2561 t.observe(50, Some(60), 1_000); // replica behind
2562 t.observe(105, None, 2_000); // replica drops out mid-wait
2563 t.observe(105, None, 3_000); // still gone
2564 assert_eq!(t.journal_crossed(), Some(2_000));
2565 assert_eq!(t.replica_crossed(), None);
2566 // Reconnecting past `needed` still records the real crossing.
2567 t.observe(105, Some(150), 4_000);
2568 assert_eq!(t.replica_crossed(), Some(4_000));
2569 }
2570
2571 #[cfg(feature = "tick-to-trade")]
2572 #[test]
2573 fn gate_cross_tracker_records_nothing_when_no_replica_clause() {
2574 // `local` never binds on a replica, so `policy_replica_cursor`
2575 // returns `None` for the whole wait: was_below stays false and
2576 // no replica sample is produced.
2577 let mut t = GateCrossTracker::new(100);
2578 t.observe(50, None, 1_000);
2579 t.observe(105, None, 2_000);
2580 assert_eq!(t.journal_crossed(), Some(2_000));
2581 assert_eq!(t.replica_crossed(), None);
2582 }
2583
2584 // -- DegradationLogger flap-suppression --
2585 //
2586 // The logger gates transition logs on a sustained-state hold so a
2587 // replica flapping at sub-second cadence doesn't spam the journal.
2588 // These tests don't observe the logs themselves (tracing is
2589 // process-global and brittle to capture in unit tests); they
2590 // assert the underlying state machine via the `policy_degraded`
2591 // gauge, which the logger updates on every tick regardless of
2592 // log emission.
2593
2594 fn logger_test_policy() -> crate::durability_policy::Policy {
2595 parse("persisted>=2").unwrap()
2596 }
2597
2598 /// Tick the logger N times at `step` intervals, alternating
2599 /// `degraded` per call. Returns the gauge value after the last
2600 /// tick — useful for asserting that flap cycles don't leak the
2601 /// AtomicBool into a wrong terminal state.
2602 fn drive_logger(
2603 logger: &mut DegradationLogger,
2604 utilization: &StageUtilization,
2605 policy: &crate::durability_policy::Policy,
2606 start: Instant,
2607 states: &[bool],
2608 step: Duration,
2609 ) -> bool {
2610 for (i, &state) in states.iter().enumerate() {
2611 let now = start + step.checked_mul(i as u32).unwrap_or(Duration::ZERO);
2612 logger.tick(policy, utilization, state, now, Duration::from_secs(5));
2613 }
2614 utilization.policy_degraded.load(Ordering::Relaxed)
2615 }
2616
2617 #[test]
2618 fn logger_gauge_tracks_state_immediately() {
2619 // The /healthz gauge reflects the *latest* state on every
2620 // tick — this is what dashboards / alerts read. Sustained-
2621 // state gating only affects the warn/info log emission.
2622 let p = logger_test_policy();
2623 let utilization = StageUtilization::new();
2624 let now = Instant::now();
2625 let mut logger = DegradationLogger::new(now);
2626
2627 logger.tick(&p, &utilization, true, now, Duration::from_secs(5));
2628 assert!(utilization.policy_degraded.load(Ordering::Relaxed));
2629
2630 logger.tick(
2631 &p,
2632 &utilization,
2633 false,
2634 now + Duration::from_millis(50),
2635 Duration::from_secs(5),
2636 );
2637 assert!(!utilization.policy_degraded.load(Ordering::Relaxed));
2638 }
2639
2640 #[test]
2641 fn logger_starting_degraded_marks_initial_state_logged() {
2642 // `new_starting_degraded` emits the startup warn and treats
2643 // the state as already-logged so the next tick at the same
2644 // cluster shape doesn't re-emit instantly. The gauge starts
2645 // at 1.
2646 let p = logger_test_policy();
2647 let utilization = StageUtilization::new();
2648 let now = Instant::now();
2649 let mut logger = DegradationLogger::new_starting_degraded(now, &p);
2650 // The logger doesn't write the gauge from the constructor —
2651 // first tick does. Tick at the same state to settle the
2652 // gauge. No new log line should fire (state hasn't changed).
2653 logger.tick(
2654 &p,
2655 &utilization,
2656 true,
2657 now + Duration::from_millis(10),
2658 Duration::from_secs(5),
2659 );
2660 assert!(utilization.policy_degraded.load(Ordering::Relaxed));
2661 }
2662
2663 #[test]
2664 fn logger_accumulates_degraded_seconds_only_while_degraded() {
2665 // The `policy_degraded_nanos` counter must advance by exactly
2666 // the wall-clock time spent in the degraded state and stay flat
2667 // while healthy. Each tick attributes the interval since the
2668 // previous tick to the state observed at that previous tick.
2669 let p = logger_test_policy();
2670 let utilization = StageUtilization::new();
2671 let start = Instant::now();
2672 let mut logger = DegradationLogger::new(start);
2673 let sec = Duration::from_secs(1);
2674
2675 // t0: healthy -> degraded. The zero-length interval before the
2676 // transition is attributed to the healthy start: no accrual.
2677 logger.tick(&p, &utilization, true, start, Duration::from_secs(5));
2678 assert_eq!(utilization.policy_degraded_nanos.load(Ordering::Relaxed), 0);
2679
2680 // t0..t1 spent degraded -> +1s.
2681 logger.tick(&p, &utilization, true, start + sec, Duration::from_secs(5));
2682 // t1..t2 still degraded, then flips healthy at the tick -> +1s.
2683 logger.tick(
2684 &p,
2685 &utilization,
2686 false,
2687 start + 2 * sec,
2688 Duration::from_secs(5),
2689 );
2690 assert_eq!(
2691 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2692 2 * sec.as_nanos() as u64
2693 );
2694
2695 // t2..t3 spent healthy -> counter holds flat.
2696 logger.tick(
2697 &p,
2698 &utilization,
2699 false,
2700 start + 3 * sec,
2701 Duration::from_secs(5),
2702 );
2703 assert_eq!(
2704 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2705 2 * sec.as_nanos() as u64
2706 );
2707 }
2708
2709 #[test]
2710 fn logger_starting_degraded_accrues_from_construction() {
2711 // A primary that boots already-degraded (e.g. `hybrid` with no
2712 // replica yet) must accrue from construction, not from the first
2713 // observed transition — `new_starting_degraded` seeds the
2714 // degraded state so the first tick's interval counts.
2715 let p = logger_test_policy();
2716 let utilization = StageUtilization::new();
2717 let start = Instant::now();
2718 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
2719
2720 logger.tick(
2721 &p,
2722 &utilization,
2723 true,
2724 start + Duration::from_secs(1),
2725 Duration::from_secs(5),
2726 );
2727 assert_eq!(
2728 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2729 Duration::from_secs(1).as_nanos() as u64
2730 );
2731 }
2732
2733 #[test]
2734 fn logger_reseed_flushes_in_flight_degraded_accrual() {
2735 // A runtime mode swap re-seeds the logger. On the gate-wait path
2736 // the swap can land after many seconds of wedged-degraded time
2737 // with no intervening tick, so `reseed` must flush that interval
2738 // before resetting — otherwise the whole wedge is silently lost,
2739 // which is exactly the incident the metric exists to measure.
2740 let p = logger_test_policy();
2741 let utilization = StageUtilization::new();
2742 let start = Instant::now();
2743 let sec = Duration::from_secs(1);
2744
2745 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
2746 logger.tick(&p, &utilization, true, start, Duration::from_secs(5));
2747 assert_eq!(utilization.policy_degraded_nanos.load(Ordering::Relaxed), 0);
2748
2749 // 30s wedged-degraded with no tick (frozen spin), then swap.
2750 logger.reseed(&utilization, start + 30 * sec);
2751 assert_eq!(
2752 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2753 30 * sec.as_nanos() as u64
2754 );
2755
2756 // Post-reseed the logger is healthy-start; a healthy interval
2757 // does not accrue, and `last_tick` was rebased to the swap so
2758 // the next interval isn't double-counted.
2759 logger.tick(
2760 &p,
2761 &utilization,
2762 false,
2763 start + 31 * sec,
2764 Duration::from_secs(5),
2765 );
2766 assert_eq!(
2767 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2768 30 * sec.as_nanos() as u64
2769 );
2770 }
2771
2772 #[test]
2773 fn logger_starting_degraded_then_first_tick_healthy_counts_construction_interval() {
2774 // `new_starting_degraded` seeds the degraded state, so the
2775 // construction→first-tick interval is attributed degraded even
2776 // when the first observed state is already healthy (the cluster
2777 // recovered before the first tick). Locks this intentional edge.
2778 let p = logger_test_policy();
2779 let utilization = StageUtilization::new();
2780 let start = Instant::now();
2781 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
2782
2783 logger.tick(
2784 &p,
2785 &utilization,
2786 false,
2787 start + Duration::from_secs(2),
2788 Duration::from_secs(5),
2789 );
2790 assert_eq!(
2791 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2792 Duration::from_secs(2).as_nanos() as u64
2793 );
2794 }
2795
2796 #[test]
2797 fn logger_counter_matches_total_degraded_time_across_flaps() {
2798 // The cumulative counter must equal exactly the wall time spent
2799 // in degraded states across a flap sequence — the guarantee
2800 // `rate(...degraded_seconds_total)` dashboards depend on.
2801 let p = logger_test_policy();
2802 let utilization = StageUtilization::new();
2803 let start = Instant::now();
2804 let step = Duration::from_millis(500);
2805 let mut logger = DegradationLogger::new(start);
2806
2807 // State observed at tick i (fired at start + i*step). The state
2808 // set at tick i holds over [tick i, tick i+1], so degraded wall
2809 // time = the spans where the *prior* tick's state was true:
2810 // [t1,t2], [t2,t3], [t4,t5] = 3 * step.
2811 let states = [false, true, true, false, true, false];
2812 for (i, &s) in states.iter().enumerate() {
2813 logger.tick(
2814 &p,
2815 &utilization,
2816 s,
2817 start + step * i as u32,
2818 Duration::from_secs(5),
2819 );
2820 }
2821
2822 assert_eq!(
2823 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2824 (3 * step).as_nanos() as u64
2825 );
2826 }
2827
2828 #[test]
2829 fn logger_handles_rapid_flap_without_panic() {
2830 // Drive the logger through 100 alternating flips at 100ms
2831 // each (faster than the 1s flap-hold). The state machine
2832 // must remain coherent — no panics, gauge tracks final
2833 // state, and `pending_logged` doesn't get stuck.
2834 let p = logger_test_policy();
2835 let utilization = StageUtilization::new();
2836 let now = Instant::now();
2837 let mut logger = DegradationLogger::new(now);
2838 let states: Vec<bool> = (0..100u32).map(|i| i.is_multiple_of(2)).collect();
2839 let final_state = drive_logger(
2840 &mut logger,
2841 &utilization,
2842 &p,
2843 now,
2844 &states,
2845 Duration::from_millis(100),
2846 );
2847 // 100 states starting at i=0 → final state is i=99 → odd → false.
2848 assert!(!final_state);
2849 }
2850
2851 #[test]
2852 fn logger_sustained_degraded_eventually_settles() {
2853 // After a sustained-true state, the logger should be in the
2854 // "logged the onset" mode. Drive 5 ticks of degraded=true at
2855 // 500ms intervals — total 2s, well past the 1s flap-hold.
2856 // Last tick should leave gauge=1 and the heartbeat re-emit
2857 // window primed (last_log set).
2858 let p = logger_test_policy();
2859 let utilization = StageUtilization::new();
2860 let now = Instant::now();
2861 let mut logger = DegradationLogger::new(now);
2862 let final_state = drive_logger(
2863 &mut logger,
2864 &utilization,
2865 &p,
2866 now,
2867 &[true; 5],
2868 Duration::from_millis(500),
2869 );
2870 assert!(final_state);
2871 }
2872
2873 #[test]
2874 fn logger_recovery_to_healthy_settles_gauge() {
2875 // Sustained degraded → sustained healthy. Gauge should end at 0.
2876 let p = logger_test_policy();
2877 let utilization = StageUtilization::new();
2878 let now = Instant::now();
2879 let mut logger = DegradationLogger::new_starting_degraded(now, &p);
2880 let mut states = vec![true; 5]; // 2.5s degraded
2881 states.extend(vec![false; 5]); // 2.5s healthy
2882 let final_state = drive_logger(
2883 &mut logger,
2884 &utilization,
2885 &p,
2886 now,
2887 &states,
2888 Duration::from_millis(500),
2889 );
2890 assert!(!final_state);
2891 }
2892
2893 /// Regression tests for the slow-client head-of-line block fixed in
2894 /// the 2026-08 io_uring audit (docs/internal/io-uring-audit-2026-08.md,
2895 /// finding 1): `flush_sends` used to `submit_and_wait` on SENDs
2896 /// without `MSG_DONTWAIT`, and io_uring holds such a SEND's CQE back
2897 /// until the peer reads — so one zero-window client stalled every
2898 /// client's acks. These use real sockets and a real ring: the defect
2899 /// was kernel-level behaviour a mock would not reproduce.
2900 mod heartbeat {
2901 use super::super::{MAX_SEND_BUF, heartbeat_due};
2902 use super::flush_sends::entry_for;
2903 use std::os::unix::net::UnixStream;
2904 use std::time::{Duration, Instant};
2905
2906 const INTERVAL: Duration = Duration::from_secs(1);
2907 const FRAME_LEN: usize = 13;
2908
2909 /// Backdate `last_send` a full interval so only the receive-
2910 /// ability guards decide. `checked_sub` because a young
2911 /// monotonic clock can't be backdated (same pattern as the
2912 /// flush_sends tests).
2913 fn idle_entry(payload: &[u8]) -> Option<super::super::ConnectionEntry> {
2914 let (tx, _rx) = UnixStream::pair().unwrap();
2915 let mut entry = entry_for(tx, payload);
2916 entry.last_send = Instant::now().checked_sub(INTERVAL * 2)?;
2917 Some(entry)
2918 }
2919
2920 #[test]
2921 fn idle_unblocked_connection_gets_a_heartbeat() {
2922 let Some(entry) = idle_entry(&[]) else {
2923 eprintln!("monotonic clock too young to backdate; skipping");
2924 return;
2925 };
2926 assert!(heartbeat_due(&entry, Instant::now(), INTERVAL, FRAME_LEN));
2927 }
2928
2929 #[test]
2930 fn recently_active_connection_is_skipped() {
2931 let (tx, _rx) = UnixStream::pair().unwrap();
2932 let entry = entry_for(tx, &[]);
2933 assert!(
2934 !heartbeat_due(&entry, Instant::now(), INTERVAL, FRAME_LEN),
2935 "a connection inside the interval must not be pinged"
2936 );
2937 }
2938
2939 /// A blocked peer's socket is full — the frame would only grow
2940 /// `send_buf`. This is one half of the fix for the unbounded
2941 /// heartbeat growth on trickle-reading clients.
2942 #[test]
2943 fn blocked_connection_is_skipped() {
2944 let Some(mut entry) = idle_entry(&[]) else {
2945 eprintln!("monotonic clock too young to backdate; skipping");
2946 return;
2947 };
2948 entry.blocked_since = Some(Instant::now());
2949 assert!(!heartbeat_due(&entry, Instant::now(), INTERVAL, FRAME_LEN));
2950 }
2951
2952 /// The other half: heartbeats respect `MAX_SEND_BUF` like every
2953 /// other append — this was the one path that bypassed the cap.
2954 #[test]
2955 fn append_never_exceeds_the_send_buffer_cap() {
2956 let payload = vec![0u8; MAX_SEND_BUF - FRAME_LEN + 1];
2957 let Some(entry) = idle_entry(&payload) else {
2958 eprintln!("monotonic clock too young to backdate; skipping");
2959 return;
2960 };
2961 assert!(!heartbeat_due(&entry, Instant::now(), INTERVAL, FRAME_LEN));
2962
2963 let payload = vec![0u8; MAX_SEND_BUF - FRAME_LEN];
2964 let Some(entry) = idle_entry(&payload) else {
2965 eprintln!("monotonic clock too young to backdate; skipping");
2966 return;
2967 };
2968 assert!(
2969 heartbeat_due(&entry, Instant::now(), INTERVAL, FRAME_LEN),
2970 "a frame that exactly fits is allowed"
2971 );
2972 }
2973 }
2974
2975 mod flush_sends {
2976 use super::super::{
2977 BLOCKED_RETRY_INTERVAL, BLOCKED_SEND_TIMEOUT, ConnectionEntry, flush_sends,
2978 };
2979 use io_uring::IoUring;
2980 use std::collections::{HashMap, HashSet};
2981 use std::io::Read as _;
2982 use std::os::unix::io::{AsRawFd, RawFd};
2983 use std::os::unix::net::UnixStream;
2984 use std::time::{Duration, Instant};
2985
2986 pub(super) fn entry_for(stream: UnixStream, payload: &[u8]) -> ConnectionEntry {
2987 ConnectionEntry {
2988 fd: stream.as_raw_fd(),
2989 _owner: Box::new(stream),
2990 send_buf: payload.to_vec(),
2991 last_send: Instant::now(),
2992 blocked_since: None,
2993 last_send_attempt: Instant::now(),
2994 }
2995 }
2996
2997 /// Fill `fd`'s socket send buffer with non-blocking writes until
2998 /// the kernel refuses more — the state a zero-window / non-reading
2999 /// client leaves a connection in.
3000 fn fill_socket(fd: RawFd) {
3001 let junk = [0u8; 4096];
3002 loop {
3003 let n =
3004 unsafe { libc::send(fd, junk.as_ptr().cast(), junk.len(), libc::MSG_DONTWAIT) };
3005 if n < 0 {
3006 let err = std::io::Error::last_os_error();
3007 assert_eq!(
3008 err.raw_os_error(),
3009 Some(libc::EAGAIN),
3010 "unexpected errno while filling socket"
3011 );
3012 break;
3013 }
3014 }
3015 }
3016
3017 /// The defect this module exists to prevent: a peer that stops
3018 /// reading must cost the flush nothing, and healthy peers on the
3019 /// same flush must still be delivered. Against the pre-fix code
3020 /// this test never returns.
3021 #[test]
3022 fn slow_peer_does_not_block_flush_and_healthy_peer_is_delivered() {
3023 let mut ring = IoUring::new(64).unwrap();
3024 let (slow_tx, _slow_rx) = UnixStream::pair().unwrap();
3025 let (fast_tx, mut fast_rx) = UnixStream::pair().unwrap();
3026 fill_socket(slow_tx.as_raw_fd());
3027
3028 let mut connections = HashMap::new();
3029 connections.insert(1u64, entry_for(slow_tx, &[0xAA; 1024]));
3030 connections.insert(2u64, entry_for(fast_tx, b"hello"));
3031 let mut dirty: HashSet<u64> = [1, 2].into_iter().collect();
3032 let mut to_remove = Vec::new();
3033 let mut cqes = Vec::new();
3034
3035 let start = Instant::now();
3036 flush_sends(
3037 &mut ring,
3038 &mut connections,
3039 &mut dirty,
3040 &mut to_remove,
3041 &mut cqes,
3042 );
3043 // Generous bound to stay unflaky under CI load — the fixed
3044 // path completes in microseconds, the broken one only when
3045 // the slow peer reads (here: never).
3046 assert!(
3047 start.elapsed() < Duration::from_secs(1),
3048 "flush blocked on a slow peer"
3049 );
3050
3051 assert!(to_remove.is_empty(), "nobody dropped on first refusal");
3052 let slow = &connections[&1];
3053 assert!(
3054 !slow.send_buf.is_empty(),
3055 "slow peer keeps its undelivered bytes"
3056 );
3057 assert!(slow.blocked_since.is_some(), "slow peer marked blocked");
3058 assert!(dirty.contains(&1), "slow peer stays dirty for retry");
3059
3060 assert!(connections[&2].send_buf.is_empty(), "healthy peer drained");
3061 assert!(!dirty.contains(&2), "healthy peer leaves the dirty set");
3062 fast_rx
3063 .set_read_timeout(Some(Duration::from_secs(1)))
3064 .unwrap();
3065 let mut buf = [0u8; 5];
3066 fast_rx.read_exact(&mut buf).unwrap();
3067 assert_eq!(&buf, b"hello", "healthy peer's bytes reached the socket");
3068 }
3069
3070 /// A payload larger than the socket buffer must be partially
3071 /// delivered, the remainder kept, and the connection treated as
3072 /// blocked (an immediate retry would only report EAGAIN).
3073 #[test]
3074 fn partial_send_keeps_remainder_and_marks_blocked() {
3075 let mut ring = IoUring::new(64).unwrap();
3076 let (tx, _rx) = UnixStream::pair().unwrap();
3077 // Shrink the send buffer so the payload cannot fit in one go.
3078 let sz: libc::c_int = 8192;
3079 let rc = unsafe {
3080 libc::setsockopt(
3081 tx.as_raw_fd(),
3082 libc::SOL_SOCKET,
3083 libc::SO_SNDBUF,
3084 (&raw const sz).cast(),
3085 size_of::<libc::c_int>() as libc::socklen_t,
3086 )
3087 };
3088 assert_eq!(rc, 0, "setsockopt(SO_SNDBUF) failed");
3089 let payload = vec![0x55u8; 512 * 1024];
3090
3091 // Enter the flush as an already-blocked peer with a stale
3092 // (but unexpired) block timestamp and an expired pacing
3093 // window, so the partial delivery below must *restart* the
3094 // blocked clock — the behaviour that keeps a slow-but-
3095 // draining client alive past BLOCKED_SEND_TIMEOUT.
3096 let Some(stale_block) = Instant::now().checked_sub(BLOCKED_SEND_TIMEOUT / 2) else {
3097 eprintln!("monotonic clock too young to backdate; skipping");
3098 return;
3099 };
3100 let mut entry = entry_for(tx, &payload);
3101 entry.blocked_since = Some(stale_block);
3102 entry.last_send_attempt = stale_block;
3103
3104 let mut connections = HashMap::new();
3105 connections.insert(1u64, entry);
3106 let mut dirty: HashSet<u64> = [1].into_iter().collect();
3107 let mut to_remove = Vec::new();
3108 let mut cqes = Vec::new();
3109
3110 flush_sends(
3111 &mut ring,
3112 &mut connections,
3113 &mut dirty,
3114 &mut to_remove,
3115 &mut cqes,
3116 );
3117
3118 let entry = &connections[&1];
3119 assert!(entry.send_buf.len() < payload.len(), "some bytes were sent");
3120 assert!(!entry.send_buf.is_empty(), "remainder kept for retry");
3121 let refreshed = entry.blocked_since.expect("partial send marks blocked");
3122 assert!(
3123 refreshed > stale_block,
3124 "forward progress restarts the blocked clock"
3125 );
3126 assert!(dirty.contains(&1));
3127 assert!(to_remove.is_empty());
3128 }
3129
3130 /// A connection blocked past `BLOCKED_SEND_TIMEOUT` is dropped —
3131 /// the guard for clients that stop reading during quiet periods,
3132 /// where `MAX_SEND_BUF` never trips because nothing accumulates.
3133 #[test]
3134 fn blocked_past_timeout_is_dropped() {
3135 let mut ring = IoUring::new(64).unwrap();
3136 let (tx, _rx) = UnixStream::pair().unwrap();
3137 fill_socket(tx.as_raw_fd());
3138
3139 let mut entry = entry_for(tx, &[1u8; 64]);
3140 // `checked_sub`: a plain `-` panics when the monotonic clock
3141 // is younger than the timeout (fresh-boot CI microVMs).
3142 let Some(expired) = Instant::now().checked_sub(BLOCKED_SEND_TIMEOUT) else {
3143 eprintln!("monotonic clock too young to backdate; skipping");
3144 return;
3145 };
3146 entry.blocked_since = Some(expired);
3147 let mut connections = HashMap::new();
3148 connections.insert(7u64, entry);
3149 let mut dirty: HashSet<u64> = [7].into_iter().collect();
3150 let mut to_remove = Vec::new();
3151 let mut cqes = Vec::new();
3152
3153 flush_sends(
3154 &mut ring,
3155 &mut connections,
3156 &mut dirty,
3157 &mut to_remove,
3158 &mut cqes,
3159 );
3160
3161 assert_eq!(to_remove, vec![7], "timed-out peer queued for removal");
3162 assert!(!dirty.contains(&7), "dropped peer leaves the dirty set");
3163 }
3164
3165 /// A blocked connection retried a moment ago is skipped — the
3166 /// pacing that keeps a busy-spinning stage from probing a full
3167 /// socket once per loop iteration.
3168 #[test]
3169 fn blocked_retry_is_paced() {
3170 let mut ring = IoUring::new(64).unwrap();
3171 let (tx, _rx) = UnixStream::pair().unwrap();
3172 fill_socket(tx.as_raw_fd());
3173
3174 let mut entry = entry_for(tx, &[1u8; 64]);
3175 entry.blocked_since = Some(Instant::now());
3176 // A future attempt timestamp makes the pacing skip
3177 // deterministic: `duration_since` saturates to zero, so no
3178 // CI-load preemption between here and the flush's own clock
3179 // read can open the 100 µs window and flake the assertion.
3180 entry.last_send_attempt = Instant::now() + Duration::from_secs(1);
3181 let attempted_at = entry.last_send_attempt;
3182 let mut connections = HashMap::new();
3183 connections.insert(3u64, entry);
3184 let mut dirty: HashSet<u64> = [3].into_iter().collect();
3185 let mut to_remove = Vec::new();
3186 let mut cqes = Vec::new();
3187
3188 flush_sends(
3189 &mut ring,
3190 &mut connections,
3191 &mut dirty,
3192 &mut to_remove,
3193 &mut cqes,
3194 );
3195
3196 assert_eq!(
3197 connections[&3].last_send_attempt, attempted_at,
3198 "no SEND submitted inside the pacing window"
3199 );
3200 assert!(dirty.contains(&3), "paced peer stays dirty");
3201 assert!(to_remove.is_empty());
3202
3203 // Outside the pacing window the retry happens: backdate the
3204 // last attempt and verify the attempt timestamp advances.
3205 let Some(backdated) = Instant::now().checked_sub(BLOCKED_RETRY_INTERVAL * 2) else {
3206 eprintln!("monotonic clock too young to backdate; skipping");
3207 return;
3208 };
3209 connections.get_mut(&3).unwrap().last_send_attempt = backdated;
3210 flush_sends(
3211 &mut ring,
3212 &mut connections,
3213 &mut dirty,
3214 &mut to_remove,
3215 &mut cqes,
3216 );
3217 assert!(
3218 connections[&3].last_send_attempt > backdated,
3219 "retry submitted once the pacing window elapsed"
3220 );
3221 }
3222
3223 /// Review finding F1 (io-uring-audit-2026-08.md): a
3224 /// response-initiated drop must tear down the *whole* socket and
3225 /// release the `max_connections` permit. The reader holds its
3226 /// own dup of the socket, so merely dropping this stage's entry
3227 /// (closing our dup) leaves the socket open — the EOF below must
3228 /// arrive *despite* a live second dup, which only shutdown(2)
3229 /// achieves.
3230 #[test]
3231 fn teardown_shuts_the_socket_despite_other_dups_and_releases_the_permit() {
3232 use std::sync::atomic::{AtomicU64, Ordering};
3233
3234 let (tx, mut peer) = UnixStream::pair().unwrap();
3235 // Simulates the reader's half: still open across the drop.
3236 let reader_dup = tx.try_clone().unwrap();
3237 let entry = entry_for(tx, &[]);
3238 let active = AtomicU64::new(1);
3239
3240 super::super::teardown_dropped(entry, &active);
3241
3242 assert_eq!(active.load(Ordering::Relaxed), 0, "permit released");
3243 peer.set_read_timeout(Some(Duration::from_secs(1))).unwrap();
3244 let mut buf = [0u8; 1];
3245 assert_eq!(
3246 peer.read(&mut buf).expect("EOF, not a timeout"),
3247 0,
3248 "peer observes EOF even though another dup is still open"
3249 );
3250 drop(reader_dup);
3251 }
3252 }
3253}