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, 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::{CursorView, DurabilityMode, EvalStatus, Policy};
24use crate::replication::ReplicationMetrics;
25use melin_app::Application;
26use melin_app::amortized_timer::AmortizedTimer;
27use melin_transport_core::pipeline::{OutputPayload, OutputSlot, StageUtilization};
28#[cfg(feature = "latency-trace")]
29use melin_transport_core::trace;
30use melin_transport_core::{DurableWireSeqCursor, WireSeq};
31
32use melin_wire_protocol::control::TransportResponse;
33use melin_wire_protocol::control_codec;
34
35/// Maximum number of output slots consumed per batch.
36const MAX_BATCH: usize = 1024;
37
38/// Maximum encoded response size. PositionSnapshot is the largest variant
39/// at up to 330 bytes (length(4) + tag(1) + account(4) + count(1) +
40/// 16*(currency(4)+free(8)+reserved(8))). 512 bytes covers all variants.
41const MAX_RESPONSE_BUF: usize = 512;
42
43/// io_uring submission queue depth for sends. Must be ≥ max concurrent
44/// connections to avoid SQ overflow when all connections are dirty.
45/// Power of 2 for io_uring alignment. 4096 supports 1024+ client
46/// benchmarks where all connections flush simultaneously.
47const RING_SIZE: u32 = 4096;
48
49/// Maximum accumulated send buffer per connection (64 KiB). If a client
50/// falls behind and the buffer exceeds this, the connection is dropped.
51/// 64 KiB holds ~500 response frames — well beyond any reasonable lag.
52const MAX_SEND_BUF: usize = 64 * 1024;
53
54pub use crate::ControlEvent;
55
56/// Encoder type alias: response encoder bound to the application's
57/// `Report` / `QueryResponse` types. Hides the long
58/// `dyn ResponseEncoder<Report = ..., Query = ...>` at call sites.
59pub type ResponseEncoderArc<A> = Arc<
60 dyn melin_app::encoder::ResponseEncoder<
61 Report = <A as Application>::Report,
62 Query = <A as Application>::QueryResponse,
63 >,
64>;
65
66/// Configuration and shared state for the response stage.
67pub struct Response<A: Application> {
68 /// Highest wire seq durably persisted on the primary's journal.
69 /// In the same sequence space as `OutputSlot.wire_seq` and the
70 /// replica metrics (`metrics.in_memory_sequence` /
71 /// `metrics.acked_sequence`), so the durability gate can compare
72 /// these values numerically and the comparison is meaningful
73 /// regardless of `starting_sequence` (fresh vs recovered primary).
74 /// Typed [`DurableWireSeqCursor`] so the gate cannot be wired to a
75 /// ring-space counter — the pre-v14 bug class. Updated by the
76 /// journal stage after every fsync batch via `set_last_seq_publisher`.
77 pub journal_persisted_wire_seq: DurableWireSeqCursor,
78 /// Operator-selected durability mode, published through a shared
79 /// [`AtomicU8`] so the admin `DURABILITY` command can swap it at
80 /// runtime without restarting the node. The response stage reads
81 /// this once per gate iteration with a relaxed load (cheaper than a
82 /// `Mutex` or refcounted `Arc<Policy>` snapshot) and rebuilds its
83 /// local [`Policy`] when the byte changes. See
84 /// [`crate::durability_policy::DurabilityMode::as_u8`] for the
85 /// encoding.
86 pub durability_mode: Arc<std::sync::atomic::AtomicU8>,
87 /// Per-slot replica cursors. `None` for standalone deployments
88 /// (no replication wiring) — the policy then evaluates against the
89 /// primary alone.
90 pub replication_metrics: Option<Arc<ReplicationMetrics>>,
91 /// Per-slot replica active flags. Only "true" slots are included in
92 /// the cursor view fed to `Policy::evaluate`, so disconnected slots
93 /// don't pollute the view with stale zero cursors. When the
94 /// resulting view is too small to satisfy a clause, the policy
95 /// reports degraded and the gate stalls.
96 /// Mirrors `replication_metrics` — `None` in standalone.
97 pub replica_active: Option<[Arc<AtomicBool>; 2]>,
98 pub heartbeat_interval: Option<Duration>,
99 pub busy_spin: bool,
100 pub utilization: Arc<StageUtilization>,
101 /// Wire encoder for application-shaped payloads. Constructed
102 /// once at boot (`Arc::new(ExchangeResponseEncoder)`) and shared
103 /// with the DPDK response stage.
104 pub encoder: ResponseEncoderArc<A>,
105 /// Node fencing state. When latched (a higher epoch was observed), the
106 /// stage exits *without* the best-effort flush — in-flight responses
107 /// for orders on a superseded epoch must not be acknowledged. Fencing
108 /// co-sets `shutdown`, so the latch is only consulted on the shutdown
109 /// path (zero steady-state cost). See `crate::fence`.
110 pub fence_state: Arc<melin_transport_core::fence::FenceState>,
111}
112
113/// Per-connection state for batched io_uring sends.
114struct ConnectionEntry {
115 fd: RawFd,
116 /// Owns the write half of the socket to keep the fd alive.
117 _owner: Box<dyn Send>,
118 /// Accumulates encoded response frames between flushes.
119 /// The full wire frame (length prefix + payload) is appended here.
120 /// Vec's internal data pointer is heap-stable, so io_uring SEND SQEs
121 /// referencing `as_ptr()` remain valid even if the HashMap relocates
122 /// this struct — as long as we don't reallocate the Vec during in-flight sends.
123 send_buf: Vec<u8>,
124 /// Last time data was sent to this connection. Used for heartbeat scheduling.
125 last_send: Instant,
126}
127
128/// Run the io_uring response stage loop. Blocks the calling thread until shutdown.
129///
130/// Consumes from the output SPSC, waits for durability confirmation, and
131/// sends responses via io_uring SEND.
132///
133/// Durability gating: every gate iteration reads the journal cursor
134/// (primary persisted) plus per-slot replica cursors (in-memory and
135/// persisted) from `replication_metrics` and feeds them through the
136/// configured [`Policy`]. See [`evaluate_durability`].
137pub fn run<A: Application>(
138 mut consumer: ring::Consumer<OutputSlot<A::Report, A::QueryResponse>>,
139 control_rx: mpsc::Receiver<ControlEvent>,
140 config: Response<A>,
141 shutdown: &AtomicBool,
142) {
143 let Response {
144 journal_persisted_wire_seq,
145 durability_mode,
146 replication_metrics,
147 replica_active,
148 heartbeat_interval,
149 busy_spin,
150 utilization,
151 encoder,
152 fence_state,
153 } = config;
154 // Resolve the starting mode from the shared atomic and derive the
155 // local Policy. The atomic is the single source of truth across the
156 // process lifetime; the response thread keeps a thread-local copy
157 // for cheap per-iteration use and rebuilds it when an admin
158 // `DURABILITY` command swaps the atomic. Initialise as Hybrid (the
159 // default mode) if the atomic ever holds a corrupted byte — better
160 // than panicking on a degraded process and matches the default
161 // operators see at boot.
162 let mut active_mode =
163 DurabilityMode::from_u8(durability_mode.load(std::sync::atomic::Ordering::Relaxed))
164 .unwrap_or_else(|| {
165 tracing::error!(
166 "durability_mode atomic held a corrupted byte at startup; defaulting to hybrid"
167 );
168 DurabilityMode::Hybrid
169 });
170 let mut policy = active_mode.to_policy();
171 let mut ring =
172 IoUring::new(RING_SIZE).expect("failed to create io_uring instance for response stage");
173
174 // Connection table: maps connection IDs to their state.
175 // HashMap for O(1) lookup. Pre-sized for a reasonable number of concurrent clients.
176 let mut connections: HashMap<u64, ConnectionEntry> = HashMap::with_capacity(256);
177
178 let mut batch = [OutputSlot::<A::Report, A::QueryResponse>::default(); MAX_BATCH];
179 let mut encode_buf = [0u8; MAX_RESPONSE_BUF];
180
181 // Cached durability position to avoid atomic reads on every slot.
182 // Initialised below from the policy's startup evaluation; updated
183 // via `evaluate_durability` on every gate iteration.
184 let mut cached_durable_pos: u64;
185
186 // Degradation logger. Tracks transitions, suppresses sub-second
187 // flap noise, and drives the `/healthz` `policy_degraded` gauge.
188 // See `DegradationLogger` for the full state machine. Initialised
189 // below from the policy's startup evaluation so an unsatisfiable
190 // policy (e.g. a primary that just lost both replicas while
191 // running `hybrid` or `durably-replicated`) is visible immediately
192 // on `/healthz` and in the journal.
193 let startup_now = Instant::now();
194 let mut last_policy_check = startup_now;
195 /// Re-emit interval for the "still degraded" reminder.
196 const DEGRADED_LOG_INTERVAL: Duration = Duration::from_secs(5);
197 /// Cadence at which the idle path re-evaluates the policy. Bounds
198 /// the lag between a connection-state change and the `/healthz`
199 /// gauge / warn-log reflecting it. Cheap (a handful of atomic
200 /// loads + the policy evaluator) at this rate.
201 const POLICY_CHECK_INTERVAL: Duration = Duration::from_secs(1);
202 /// Cadence at which the gate-wait spin folds elapsed time into the
203 /// degraded-duration counter while the durability gate is stalled.
204 /// Tighter than the idle cadence — it bounds the boundary error when
205 /// a degradation begins or flips mid-wedge, which matters most for
206 /// short stalls. The accrual tick is gated by this period, but the
207 /// clock read behind it is gated by the `AmortizedTimer` mask, so the
208 /// effective resolution is `max(this, the mask's clock-read cadence)`.
209 /// The mask reads the clock ~every 6.5 ms at this spin's rate
210 /// (`AmortizedTimer::CHECK_MASK` is `2^16`), finer than the 10 ms
211 /// here, so this cadence is the binding one and is realized in full.
212 const GATE_ACCRUAL_INTERVAL: Duration = Duration::from_millis(10);
213
214 // Initial evaluation so the cached durable position and the
215 // `/healthz` gauge reflect the cluster's startup shape before
216 // the first batch arrives.
217 let mut degraded_logger;
218 {
219 let journal_pos = journal_persisted_wire_seq.load();
220 let metrics_ref = replication_metrics.as_deref();
221 let active_ref = replica_active.as_ref();
222 let status = evaluate_durability(&policy, journal_pos, metrics_ref, active_ref);
223 cached_durable_pos = status.durable_pos;
224 utilization
225 .policy_degraded
226 .store(status.degraded, Ordering::Relaxed);
227 degraded_logger = if status.degraded {
228 DegradationLogger::new_starting_degraded(startup_now, &policy)
229 } else {
230 DegradationLogger::new(startup_now)
231 };
232 }
233
234 // Stage histograms registered with the global registry — see
235 // `melin_transport_core::trace`. The four breakdown stages
236 // (journal-wait, replica-wait, encode, egress) feed the bench's
237 // tick-to-trade decomposition; spsc/dispatch/server-e2e are kept
238 // alongside as overall sanity checks.
239 #[cfg(feature = "latency-trace")]
240 let mut spsc_rec =
241 trace::register_stage("response: SPSC wakeup (matching publish → response consume)");
242 #[cfg(feature = "latency-trace")]
243 let mut dispatch_rec = trace::register_stage("response: dispatch (consume → socket write)");
244 #[cfg(feature = "latency-trace")]
245 let mut server_e2e_rec = trace::register_stage("server e2e (reader recv → response flush)");
246 // Tick-to-trade breakdown: per-slot wait observed for each
247 // durability path (recorded only when the gate actually held us
248 // up — cache-hit paths skip to avoid inflating the metric with
249 // crossings that happened before we noticed). Encode is wall-time
250 // around `encode_transport_response`. Egress wraps a `flush_sends`
251 // call (one sample per io_uring flush, batching many slots).
252 // Gated on `tick-to-trade`, not `latency-trace`, because these
253 // stages roughly double the hot-path mutex traffic vs the lighter
254 // 4-stage mode.
255 #[cfg(feature = "tick-to-trade")]
256 let mut journal_wait_rec =
257 trace::register_stage("response: journal-wait (match_complete → journal cursor crossed)");
258 #[cfg(feature = "tick-to-trade")]
259 let mut replica_wait_rec = trace::register_stage(
260 "response: replica-wait (match_complete → replication cursor crossed)",
261 );
262 #[cfg(feature = "tick-to-trade")]
263 let mut encode_rec = trace::register_stage("response: encode (per-kind wire encoding)");
264 #[cfg(feature = "tick-to-trade")]
265 let mut egress_rec = trace::register_stage("response: egress (flush_sends elapsed)");
266
267 // Track connections with buffered (unflushed) writes across batches.
268 let mut dirty_connections: HashSet<u64> = HashSet::new();
269
270 // Connections to remove after flush (send errors).
271 let mut to_remove: Vec<u64> = Vec::new();
272
273 // Pre-allocated CQE collection buffer. Must collect CQEs before
274 // processing because the CQ borrow must end before mutating connections.
275 // Pre-sized to RING_SIZE to avoid per-iteration heap allocation.
276 let mut cqes: Vec<(u64, i32)> = Vec::with_capacity(RING_SIZE as usize);
277
278 // Pre-encode the heartbeat response frame once. Full wire frame
279 // (length prefix + tag) for direct append to send_buf.
280 let heartbeat_wire_frame = {
281 let mut buf = [0u8; 8];
282 let written =
283 control_codec::encode_transport_response(&TransportResponse::Heartbeat, &mut buf)
284 .expect("heartbeat encodes");
285 buf[..written].to_vec()
286 };
287
288 // Coarse timestamp for heartbeat scan — avoids Instant::now() on every spin.
289 let mut last_heartbeat_scan = Instant::now();
290
291 // Adaptive spin: spin first (fast wakeup), yield after threshold.
292 let mut idle_spins: u32 = 0;
293
294 let mut busy_count: u64 = 0;
295 let mut idle_count: u64 = 0;
296
297 // Paces accrual ticks inside the durability gate-wait spin so the
298 // degraded-duration counter keeps advancing during a hard stall.
299 // Declared once at function scope (not per gate entry) so the normal
300 // gated path — entered briefly whenever durability lags by a few µs —
301 // pays no extra `Instant::now()`; the amortized mask only reads the
302 // clock once per ~1 M cumulative spin iterations.
303 let mut gate_accrual_timer = AmortizedTimer::new();
304
305 loop {
306 // Observe runtime mode swaps from the admin `DURABILITY`
307 // command. Relaxed load (single writer is the admin handler,
308 // single reader is this thread). When the byte changes,
309 // rebuild the local Policy and reset the cached durable
310 // position so the next gate evaluation starts from a clean
311 // slate under the new shape; log the transition for the audit
312 // trail. An unknown byte is treated as memory corruption: we
313 // log and keep the prior mode rather than silently downgrading.
314 let observed_byte = durability_mode.load(Ordering::Relaxed);
315 if observed_byte != active_mode.as_u8() {
316 match DurabilityMode::from_u8(observed_byte) {
317 Some(next) => {
318 tracing::info!(
319 prev = active_mode.as_str(),
320 next = next.as_str(),
321 "durability mode swapped at runtime"
322 );
323 active_mode = next;
324 policy = active_mode.to_policy();
325 // The fresh policy may evaluate degraded/undegraded
326 // differently against the same cluster shape; let
327 // the next gate evaluation re-derive.
328 cached_durable_pos = 0;
329 // Re-seed the degradation logger so a transition
330 // out of (or into) degraded under the new policy
331 // surfaces immediately rather than waiting for the
332 // sustained-state hold to roll over. Flushes accrual
333 // first so pre-swap degraded time isn't dropped.
334 degraded_logger.reseed(&utilization, Instant::now());
335 }
336 None => {
337 tracing::error!(
338 byte = observed_byte,
339 "durability_mode atomic held a corrupted byte; retaining prior mode"
340 );
341 }
342 }
343 }
344
345 if shutdown.load(Ordering::Relaxed) {
346 // Fence: a superseded ex-primary must not acknowledge any
347 // further in-flight work — skip the best-effort flush so
348 // responses buffered for orders on the old epoch are dropped
349 // (the client sees a connection reset and reconciles on
350 // reconnect). Checked only here, not per iteration: fencing
351 // always co-sets `shutdown` (`FenceState::fence_if_superseded`
352 // owns that invariant), so this branch is the first one a
353 // fenced node reaches and the steady-state loop pays nothing.
354 let flush = !fence_state.is_fenced();
355 // Best-effort flush before shutdown.
356 if flush && !dirty_connections.is_empty() {
357 flush_sends(
358 &mut ring,
359 &mut connections,
360 &dirty_connections,
361 &mut to_remove,
362 &mut cqes,
363 );
364 dirty_connections.clear();
365 }
366 utilization.busy.store(busy_count, Ordering::Relaxed);
367 utilization.idle.store(idle_count, Ordering::Relaxed);
368 #[cfg(feature = "pipeline-stats")]
369 print_utilization("response", busy_count, idle_count);
370 return;
371 }
372
373 // Poll control channel (non-blocking) for connect/disconnect.
374 while let Ok(event) = control_rx.try_recv() {
375 match event {
376 ControlEvent::Connected {
377 connection_id,
378 fd,
379 writer,
380 } => {
381 // The writer keeps the fd alive — store it as the owner.
382 let owner: Box<dyn Send> = Box::new(writer);
383 connections.insert(
384 connection_id,
385 ConnectionEntry {
386 fd,
387 _owner: owner,
388 send_buf: Vec::with_capacity(4096),
389 last_send: Instant::now(),
390 },
391 );
392 }
393 ControlEvent::Disconnected { connection_id } => {
394 connections.remove(&connection_id);
395 dirty_connections.remove(&connection_id);
396 }
397 }
398 }
399
400 // Consume output slots from matching stage.
401 let count = consumer.consume_batch(&mut batch, MAX_BATCH);
402 if count == 0 {
403 // SPSC is empty — flush all dirty connections via io_uring.
404 // This is the response-data egress path; heartbeat flushes
405 // below aren't sampled because they're admin traffic, not
406 // on the client RTT path.
407 if !dirty_connections.is_empty() {
408 #[cfg(feature = "tick-to-trade")]
409 let egress_start = trace::mono_trace_ns();
410 flush_sends(
411 &mut ring,
412 &mut connections,
413 &dirty_connections,
414 &mut to_remove,
415 &mut cqes,
416 );
417 #[cfg(feature = "tick-to-trade")]
418 egress_rec.record_elapsed(egress_start, trace::mono_trace_ns());
419 for conn_id in to_remove.drain(..) {
420 connections.remove(&conn_id);
421 }
422 dirty_connections.clear();
423 }
424
425 // Send heartbeats to idle connections. Only checked during
426 // idle periods (SPSC empty) to avoid overhead on the hot path.
427 if let Some(interval) = heartbeat_interval {
428 let now = Instant::now();
429 // Coarse gate: only scan at most once per second.
430 if now.duration_since(last_heartbeat_scan) >= Duration::from_secs(1) {
431 last_heartbeat_scan = now;
432 for (&conn_id, entry) in connections.iter_mut() {
433 if now.duration_since(entry.last_send) >= interval {
434 entry.send_buf.extend_from_slice(&heartbeat_wire_frame);
435 dirty_connections.insert(conn_id);
436 entry.last_send = now;
437 }
438 }
439 // Flush the heartbeat sends immediately.
440 if !dirty_connections.is_empty() {
441 flush_sends(
442 &mut ring,
443 &mut connections,
444 &dirty_connections,
445 &mut to_remove,
446 &mut cqes,
447 );
448 for conn_id in to_remove.drain(..) {
449 connections.remove(&conn_id);
450 }
451 dirty_connections.clear();
452 }
453 }
454 }
455
456 // Re-evaluate the durability policy on a slow timer so the
457 // `policy_degraded` flag and the periodic warn track the
458 // cluster's real state even on idle / quiet venues. The
459 // gate-open block also calls `update_degraded_state` after
460 // each consumed batch; this is the equivalent for the
461 // no-batch path.
462 {
463 let now_ts = Instant::now();
464 if now_ts.duration_since(last_policy_check) >= POLICY_CHECK_INTERVAL {
465 last_policy_check = now_ts;
466 let journal_pos = journal_persisted_wire_seq.load();
467 let metrics_ref = replication_metrics.as_deref();
468 let active_ref = replica_active.as_ref();
469 let status = evaluate_durability(&policy, journal_pos, metrics_ref, active_ref);
470 degraded_logger.tick(
471 &policy,
472 &utilization,
473 status.degraded,
474 now_ts,
475 DEGRADED_LOG_INTERVAL,
476 );
477 // Cache the position so the next batch's gate sees a
478 // fresh value rather than spinning from a stale cache.
479 cached_durable_pos = status.durable_pos;
480 }
481 }
482
483 idle_count += 1;
484 if idle_count.is_multiple_of(1024) {
485 utilization.busy.store(busy_count, Ordering::Relaxed);
486 utilization.idle.store(idle_count, Ordering::Relaxed);
487 }
488 if busy_spin || idle_spins < 1000 {
489 idle_spins = idle_spins.wrapping_add(1);
490 std::hint::spin_loop();
491 } else {
492 std::thread::yield_now();
493 }
494 continue;
495 }
496 idle_spins = 0;
497 busy_count += 1;
498
499 #[cfg(feature = "latency-trace")]
500 let consume_ts = trace::mono_trace_ns();
501
502 // Wait for durability confirmation before sending responses.
503 //
504 // Each iteration: read the primary journal cursor + per-slot
505 // replica cursors (both in-memory and persisted), build a
506 // `CursorView`, and evaluate the configured policy. Spin until
507 // the durable position catches up to the batch's max input_seq.
508 //
509 // Per-slot journal-wait / replica-wait tracker. See
510 // `GateCrossTracker` for the rationale (only records cursors
511 // that were actually on the critical path). Attribution uses
512 // `repl_min` = min of connected-replica persisted cursors so
513 // operators see "which subsystem to optimize" the same way as
514 // before the policy refactor.
515 #[cfg(feature = "tick-to-trade")]
516 let mut gate_tracker;
517 {
518 // Gate on `wire_seq`, not `input_seq`. `input_seq` is in
519 // local-consumer space (the matching cursor on the input
520 // ring, starts at 0 in this process) while replica metrics
521 // and the primary's `journal_persisted_wire_seq` live in
522 // wire-seq space (allocated by the journal stage starting
523 // at `starting_sequence`). A `needed` derived from
524 // `input_seq` and compared against wire-seq cursors only
525 // works when `starting_sequence == 1`; a recovered primary
526 // (or any process whose journal already has prior content
527 // pushing `starting_sequence` above 1) would silently open
528 // the gate ahead of the replica's actual replicated state.
529 //
530 // Every cursor in the policy view (`journal_persisted_wire_seq`,
531 // `metrics.in_memory_sequence`, `metrics.acked_sequence`)
532 // carries "highest wire seq known to be in that state on
533 // node X". A batch's `needed` is therefore the *exact*
534 // wire seq the gate must see — not `+1` — for the latest
535 // event in the batch to be considered durable. The legacy
536 // `+1` was load-bearing only because `input_seq` was off
537 // by `starting_sequence - 1` from wire seq; with the
538 // wire-seq stamp it would over-shoot by one event and
539 // make the gate stall an extra round-trip per response.
540 let needed = batch[..count]
541 .iter()
542 .map(|s| s.wire_seq)
543 .max()
544 .expect("non-empty batch");
545 #[cfg(feature = "tick-to-trade")]
546 {
547 gate_tracker = GateCrossTracker::new(needed);
548 }
549 // Durability-gate carve-out for halt-state output. Slots
550 // tagged `durability_bypass = true` at emission carry no
551 // engine state worth replicating before delivery — see
552 // `OutputSlot::durability_bypass` for the correctness
553 // argument. When every slot in the batch carries the flag
554 // the gate is skipped entirely, so clients receive the halt
555 // reason immediately rather than blocking on a structurally
556 // unsatisfiable policy (e.g. `Hybrid` with all replicas
557 // disconnected, which would otherwise stall the gate until
558 // peers return). If even one normal slot is present, gate
559 // the whole batch as usual — the bypass slots ride along
560 // behind the gated one, which is safe (no ordering
561 // inversion vs. a strict-gate world).
562 let needs_gate = batch[..count].iter().any(|s| !s.durability_bypass);
563 if needs_gate && cached_durable_pos < needed {
564 loop {
565 // Inside the gate-wait spin loop, also observe a
566 // mode swap. Without this, a batch whose gate
567 // becomes structurally unsatisfiable (e.g. all
568 // replicas die while a non-bypass slot is in
569 // flight under `Hybrid`) would wedge the response
570 // stage forever, even if an operator sends the
571 // remediating `DURABILITY local` — the outer loop
572 // observation never gets a chance to run. The
573 // relaxed load is ~1 cycle on x86; cheaper than
574 // the `spin_loop` hint below.
575 let observed_byte = durability_mode.load(Ordering::Relaxed);
576 if observed_byte != active_mode.as_u8()
577 && let Some(next) = DurabilityMode::from_u8(observed_byte)
578 {
579 tracing::info!(
580 prev = active_mode.as_str(),
581 next = next.as_str(),
582 "durability mode swapped during gate wait"
583 );
584 active_mode = next;
585 policy = active_mode.to_policy();
586 // Flush accrual before re-seeding so the wedged-
587 // degraded interval up to the swap isn't dropped.
588 degraded_logger.reseed(&utilization, Instant::now());
589 }
590
591 let journal_pos = journal_persisted_wire_seq.load();
592 let metrics_ref = replication_metrics.as_deref();
593 let active_ref = replica_active.as_ref();
594 let repl_min = connected_persisted_min(metrics_ref, active_ref);
595
596 #[cfg(feature = "tick-to-trade")]
597 gate_tracker.observe(journal_pos.get(), repl_min, trace::mono_trace_ns());
598
599 let status = evaluate_durability(&policy, journal_pos, metrics_ref, active_ref);
600 cached_durable_pos = status.durable_pos;
601 utilization
602 .policy_degraded
603 .store(status.degraded, Ordering::Relaxed);
604
605 // Accrue degraded time while wedged. The post-gate
606 // tick attributes the whole wait to a single state, so
607 // without this a healthy→degraded flip during the
608 // wedge would be mis-charged. `spinning = true`: this
609 // loop always spins (never yields), so the clock read
610 // behind the tick is mask-gated, landing only every
611 // ~65 k iterations (`CHECK_MASK = 2^16`) regardless of
612 // the period below.
613 if gate_accrual_timer
614 .tick(GATE_ACCRUAL_INTERVAL, true)
615 .is_some()
616 {
617 degraded_logger.tick(
618 &policy,
619 &utilization,
620 status.degraded,
621 Instant::now(),
622 DEGRADED_LOG_INTERVAL,
623 );
624 }
625
626 if cached_durable_pos >= needed {
627 // Attribution: which subsystem was slowest at
628 // the moment the gate opened. Relaxed is fine —
629 // health reads are infrequent.
630 if journal_pos.get() <= repl_min {
631 utilization.gate_journal.fetch_add(1, Ordering::Relaxed);
632 } else {
633 utilization.gate_replication.fetch_add(1, Ordering::Relaxed);
634 }
635 break;
636 }
637 std::hint::spin_loop();
638 }
639 }
640 }
641
642 let batch_now = Instant::now();
643
644 // Log degradation transitions / re-emit the reminder. Same
645 // logger the idle path uses; transitions are gated on a
646 // sustained-state hold so sub-second flap doesn't spam.
647 let degraded_now = utilization.policy_degraded.load(Ordering::Relaxed);
648 degraded_logger.tick(
649 &policy,
650 &utilization,
651 degraded_now,
652 batch_now,
653 DEGRADED_LOG_INTERVAL,
654 );
655 // Bump the idle-path's check timestamp so we don't double-
656 // tick the logger when traffic stops.
657 last_policy_check = batch_now;
658
659 for slot in &batch[..count] {
660 #[cfg(feature = "latency-trace")]
661 spsc_rec.record_elapsed(slot.match_complete_ts, consume_ts);
662
663 // Per-slot durability-gate breakdown. Recorded only when
664 // the gate actually held us up (the tracker captured a
665 // cross). Note: the cross timestamp is for the *batch's*
666 // `needed` — for slots earlier in the batch, the cursor
667 // may have crossed their individual `input_seq+1` earlier,
668 // so this systematically overestimates wait for non-last
669 // slots by up to the batch's matching span. Acceptable
670 // noise for the operator-facing breakdown; documented in
671 // `docs/benchmarking.md`.
672 #[cfg(feature = "tick-to-trade")]
673 if let Some(ts) = gate_tracker.journal_crossed() {
674 journal_wait_rec.record_elapsed(slot.match_complete_ts, ts);
675 }
676 #[cfg(feature = "tick-to-trade")]
677 if let Some(ts) = gate_tracker.replica_crossed() {
678 replica_wait_rec.record_elapsed(slot.match_complete_ts, ts);
679 }
680
681 // Each slot expands to at most two wire frames: the
682 // application payload (Report / Query / EngineError) and
683 // an optional trailing `BatchEnd` when
684 // `is_last_in_request` is set. Application-shaped
685 // payloads go through the encoder; transport-shaped
686 // frames (EngineError, BatchEnd) are encoded by the
687 // runtime directly.
688 if let Some(entry) = connections.get_mut(&slot.connection_id) {
689 // Frame 1: application payload (if any). BatchEnd
690 // payloads carry no body — the terminator below
691 // handles them via `is_last_in_request`.
692 let payload_result: Option<Result<usize, &'static str>> = match slot.payload {
693 OutputPayload::Report(ref report) => {
694 Some(encoder.encode_report(report, &mut encode_buf))
695 }
696 OutputPayload::QueryResponse(ref q) => {
697 Some(encoder.encode_query(q, &mut encode_buf))
698 }
699 OutputPayload::EngineError => Some(
700 control_codec::encode_transport_response(
701 &TransportResponse::EngineError,
702 &mut encode_buf,
703 )
704 .map_err(|_| "encode error"),
705 ),
706 OutputPayload::BatchEnd => None,
707 };
708
709 let payload_handled = if let Some(result) = payload_result {
710 #[cfg(feature = "tick-to-trade")]
711 let encode_start = trace::mono_trace_ns();
712 let outcome = append_frame(
713 result,
714 slot.connection_id,
715 entry,
716 &encode_buf,
717 batch_now,
718 &mut dirty_connections,
719 &mut to_remove,
720 );
721 #[cfg(feature = "tick-to-trade")]
722 encode_rec.record_elapsed(encode_start, trace::mono_trace_ns());
723 outcome
724 } else {
725 AppendOutcome::Continue
726 };
727
728 // Frame 2: BatchEnd terminator. Skipped if the payload
729 // append dropped the connection.
730 if matches!(payload_handled, AppendOutcome::Continue) && slot.is_last_in_request {
731 let result = control_codec::encode_transport_response(
732 &TransportResponse::BatchEnd,
733 &mut encode_buf,
734 )
735 .map_err(|_| "encode error");
736 let outcome = append_frame(
737 result,
738 slot.connection_id,
739 entry,
740 &encode_buf,
741 batch_now,
742 &mut dirty_connections,
743 &mut to_remove,
744 );
745 // Record server-side end-to-end: reader recv ->
746 // response flush. Only the BatchEnd frame carries
747 // this measurement; tracked here after the append
748 // so a dropped connection doesn't skew the metric.
749 #[cfg(feature = "latency-trace")]
750 if matches!(outcome, AppendOutcome::Continue) {
751 server_e2e_rec.record_elapsed(slot.recv_ts, trace::mono_trace_ns());
752 }
753 let _ = outcome;
754 }
755 }
756 }
757
758 // Remove connections that exceeded the send buffer limit.
759 for conn_id in to_remove.drain(..) {
760 connections.remove(&conn_id);
761 dirty_connections.remove(&conn_id);
762 }
763
764 #[cfg(feature = "latency-trace")]
765 dispatch_rec.record_elapsed(consume_ts, trace::mono_trace_ns());
766 }
767}
768
769/// Submit io_uring SEND SQEs for all dirty connections and wait for completions.
770///
771/// Outcome of a single per-frame append. `Continue` means the
772/// caller may proceed to the next frame for this slot;
773/// `ConnectionDropped` means the connection's send buffer overflowed
774/// or the encode failed, and the connection has been queued for
775/// removal — no further frames should be appended for this slot.
776#[derive(Clone, Copy)]
777enum AppendOutcome {
778 Continue,
779 ConnectionDropped,
780}
781
782/// Copy an encoded frame into the connection's send buffer with
783/// overflow checking. Splits the responsibilities the inline encode
784/// loop used to have: the caller passes in the encode result (so it
785/// can come from the `ResponseEncoder` trait for application
786/// payloads, or `encode_transport_response` for transport-shaped
787/// frames), and this helper handles size accounting + dirty
788/// tracking uniformly.
789#[allow(clippy::too_many_arguments)]
790fn append_frame(
791 result: Result<usize, &'static str>,
792 connection_id: u64,
793 entry: &mut ConnectionEntry,
794 encode_buf: &[u8],
795 batch_now: Instant,
796 dirty_connections: &mut HashSet<u64>,
797 to_remove: &mut Vec<u64>,
798) -> AppendOutcome {
799 let written = match result {
800 Ok(n) => n,
801 Err(reason) => {
802 tracing::error!(connection_id, reason, "encode error");
803 return AppendOutcome::Continue;
804 }
805 };
806
807 // Drop slow clients whose send buffer has grown too large. This
808 // prevents unbounded memory growth from a single laggy connection
809 // causing allocator pressure and tail latency spikes.
810 if entry.send_buf.len() + written > MAX_SEND_BUF {
811 debug!(
812 connection_id,
813 send_buf_len = entry.send_buf.len(),
814 "send buffer exceeded limit, dropping connection"
815 );
816 to_remove.push(connection_id);
817 return AppendOutcome::ConnectionDropped;
818 }
819
820 // Append the full wire frame to the connection's send buffer.
821 // The encoder writes [length(4) | payload], which is the complete
822 // wire format — no extra framing needed.
823 entry.send_buf.extend_from_slice(&encode_buf[..written]);
824 entry.last_send = batch_now;
825 dirty_connections.insert(connection_id);
826 AppendOutcome::Continue
827}
828
829/// Each dirty connection's accumulated send buffer is sent in a single SEND
830/// operation. Partial sends are retried until all bytes are delivered.
831/// Failed connections are collected in `to_remove` for the caller to clean up.
832fn flush_sends(
833 ring: &mut IoUring,
834 connections: &mut HashMap<u64, ConnectionEntry>,
835 dirty: &HashSet<u64>,
836 to_remove: &mut Vec<u64>,
837 cqes: &mut Vec<(u64, i32)>,
838) {
839 // Submit SEND SQEs for all dirty connections.
840 let mut pending: usize = 0;
841 for &conn_id in dirty {
842 if let Some(entry) = connections.get(&conn_id) {
843 if entry.send_buf.is_empty() {
844 continue;
845 }
846 let sqe = opcode::Send::new(
847 types::Fd(entry.fd),
848 entry.send_buf.as_ptr(),
849 entry.send_buf.len() as u32,
850 )
851 .build()
852 .user_data(conn_id);
853
854 unsafe {
855 ring.submission()
856 .push(&sqe)
857 .expect("io_uring SQ full — increase RING_SIZE");
858 }
859 pending += 1;
860 }
861 }
862
863 if pending == 0 {
864 return;
865 }
866
867 // Submit and wait for all completions.
868 if let Err(e) = ring.submit_and_wait(pending) {
869 error!(error = %e, "io_uring submit_and_wait failed in response stage");
870 return;
871 }
872
873 // Drain completions into pre-allocated buffer. Must collect to
874 // release CQ borrow before mutating connections.
875 cqes.clear();
876 cqes.extend(ring.completion().map(|cqe| (cqe.user_data(), cqe.result())));
877
878 for &(conn_id, result) in cqes.iter() {
879 if result < 0 {
880 debug!(
881 connection_id = conn_id,
882 error = result,
883 "send error, dropping connection"
884 );
885 to_remove.push(conn_id);
886 continue;
887 }
888
889 let sent = result as usize;
890 if let Some(entry) = connections.get_mut(&conn_id) {
891 if sent >= entry.send_buf.len() {
892 entry.send_buf.clear();
893 } else {
894 // Partial send — drain sent bytes, retry remainder.
895 // Rare for small response frames over TCP/UDS but must
896 // be handled for correctness (e.g., send buffer pressure).
897 entry.send_buf.drain(..sent);
898 retry_send(ring, entry, conn_id, to_remove);
899 }
900 }
901 }
902}
903
904/// Retry sending remaining bytes after a partial send. Loops until the
905/// entire buffer is delivered or an error occurs.
906fn retry_send(
907 ring: &mut IoUring,
908 entry: &mut ConnectionEntry,
909 conn_id: u64,
910 to_remove: &mut Vec<u64>,
911) {
912 while !entry.send_buf.is_empty() {
913 let sqe = opcode::Send::new(
914 types::Fd(entry.fd),
915 entry.send_buf.as_ptr(),
916 entry.send_buf.len() as u32,
917 )
918 .build()
919 .user_data(conn_id);
920
921 unsafe {
922 ring.submission()
923 .push(&sqe)
924 .expect("io_uring SQ full during send retry");
925 }
926
927 if let Err(e) = ring.submit_and_wait(1) {
928 debug!(connection_id = conn_id, error = %e, "send retry failed");
929 to_remove.push(conn_id);
930 return;
931 }
932
933 if let Some(cqe) = ring.completion().next() {
934 let result = cqe.result();
935 if result <= 0 {
936 debug!(
937 connection_id = conn_id,
938 error = result,
939 "send retry error, dropping connection"
940 );
941 to_remove.push(conn_id);
942 return;
943 }
944 let sent = result as usize;
945 if sent >= entry.send_buf.len() {
946 entry.send_buf.clear();
947 } else {
948 entry.send_buf.drain(..sent);
949 }
950 }
951 }
952}
953
954/// Evaluate the durability policy against the live cursor state.
955///
956/// Builds a `CursorView` containing the primary plus every *currently
957/// connected* replica slot and returns the highest sequence at which
958/// the policy is satisfied. The primary's in-memory cursor is modeled
959/// as `u64::MAX` because the response stage only gates events that have
960/// already been processed by the matching engine — those are trivially
961/// in-memory on the primary by construction.
962///
963/// Disconnected slots are *omitted from the view* rather than included
964/// with zero cursors. The view's `len()` reflects how many nodes are
965/// actually available; if it's too small to satisfy a clause, the
966/// policy reports degraded and the gate stalls.
967#[inline]
968pub(crate) fn evaluate_durability(
969 policy: &Policy,
970 journal_pos: WireSeq,
971 metrics: Option<&ReplicationMetrics>,
972 replica_active: Option<&[Arc<AtomicBool>; 2]>,
973) -> EvalStatus {
974 // Primary + up to 2 replica slots = 3 nodes max. The policy view is
975 // raw `u64`, all wire-seq space: `journal_pos` leaves the type system
976 // here, alongside the replica metrics gauges (the `Ack` frame's
977 // wire-seq fields verbatim).
978 let mut nodes: [[u64; 2]; 3] = [[0, 0]; 3];
979 nodes[0] = [u64::MAX, journal_pos.get()];
980 let mut len = 1;
981 if let (Some(m), Some(active)) = (metrics, replica_active) {
982 for (i, slot_active) in active.iter().enumerate() {
983 // Skip inactive slots up-front.
984 if !slot_active.load(Ordering::Acquire) {
985 continue;
986 }
987 let in_mem = m.in_memory_sequence[i].load(Ordering::Acquire);
988 let persisted = m.acked_sequence[i].load(Ordering::Acquire);
989 nodes[len] = [in_mem, persisted];
990 len += 1;
991 }
992 }
993 policy.evaluate_with_status(&CursorView::new(&nodes[..len]))
994}
995
996/// Hold-time before a state transition is committed to the log.
997/// Suppresses log spam when a replica flaps faster than this — only
998/// transitions that hold for at least this long emit warn/info
999/// entries. The `/healthz` gauge updates immediately regardless,
1000/// so dashboards and alerts still see real-time state.
1001const DEGRADED_FLAP_HOLD: Duration = Duration::from_secs(1);
1002
1003/// Tracks degradation state across calls and emits warn/info logs
1004/// with sustained-state gating + a periodic heartbeat re-emit.
1005///
1006/// The hot path calls [`Self::tick`] every gate iteration / idle
1007/// poll with the current `degraded` value and the wall clock. The
1008/// logger handles:
1009///
1010/// - Updating the `policy_degraded` health gauge immediately.
1011/// - Suppressing log lines for transitions that don't hold for at
1012/// least [`DEGRADED_FLAP_HOLD`] — a replica flapping at sub-second
1013/// cadence produces no log noise, only a quietly-updating gauge.
1014/// - Emitting a warn at the moment a sustained degraded state
1015/// crosses the hold threshold, plus a periodic re-emit every
1016/// `heartbeat_interval` while it persists.
1017/// - Emitting an info when a sustained healthy state crosses the
1018/// hold threshold (the cluster is back to its target shape and
1019/// stayed there long enough that we trust the recovery).
1020pub(crate) struct DegradationLogger {
1021 /// Last value passed to `tick`; what we'd log about if it stayed
1022 /// at this value past the hold threshold.
1023 pending_state: bool,
1024 /// When `pending_state` first appeared. Reset on every flip.
1025 pending_since: Instant,
1026 /// Whether the current pending state has been logged yet. Only
1027 /// the *first* log per sustained streak crosses; subsequent
1028 /// re-emits while degraded are heartbeat warns.
1029 pending_logged: bool,
1030 /// When the last warn fired. Drives the periodic re-emit while
1031 /// degraded.
1032 last_log: Option<Instant>,
1033 /// Wall clock of the previous accrual. The interval since this
1034 /// instant is attributed to the state observed then (`pending_state`)
1035 /// and accumulated into the `policy_degraded_nanos` counter. Advanced
1036 /// by [`Self::accrue`] — reached on every `tick` (post-gate, idle, and
1037 /// the gate-wait pacing tick) and on `reseed`.
1038 last_tick: Instant,
1039}
1040
1041impl DegradationLogger {
1042 pub(crate) fn new(now: Instant) -> Self {
1043 Self {
1044 pending_state: false,
1045 pending_since: now,
1046 pending_logged: true, // healthy is the assumed initial state; nothing to log
1047 last_log: None,
1048 last_tick: now,
1049 }
1050 }
1051
1052 /// Use when the policy is known to start in a degraded state
1053 /// (e.g. a primary in `hybrid` mode with no replica yet
1054 /// connected). Logs a startup warn immediately and treats the
1055 /// state as already-logged so the next tick doesn't re-emit.
1056 pub(crate) fn new_starting_degraded(now: Instant, policy: &Policy) -> Self {
1057 tracing::warn!(
1058 policy = %policy,
1059 "durability policy starts in degraded mode — fewer connected nodes than the target count"
1060 );
1061 Self {
1062 pending_state: true,
1063 pending_since: now,
1064 pending_logged: true,
1065 last_log: Some(now),
1066 last_tick: now,
1067 }
1068 }
1069
1070 /// Charge the interval `[last_tick, now]` to the degraded-duration
1071 /// counter when `prev_degraded` (the state observed at the previous
1072 /// tick) was degraded, then advance `last_tick`. Drives the
1073 /// `_seconds_total` counter so `rate()` reflects time-in-degraded
1074 /// continuously, even mid-incident, rather than only stepping on
1075 /// recovery. Shared by [`Self::tick`] and [`Self::reseed`] so accrual
1076 /// is never skipped on a logger lifecycle boundary.
1077 #[inline]
1078 fn accrue(&mut self, utilization: &StageUtilization, prev_degraded: bool, now: Instant) {
1079 if prev_degraded {
1080 // `duration_since` saturates to zero when `now < last_tick`;
1081 // `now` is always >= `last_tick` here (single-thread monotonic
1082 // clock), matching the plain `duration_since` used elsewhere
1083 // in this file.
1084 let elapsed = now.duration_since(self.last_tick);
1085 // `as_nanos()` is u128; one inter-tick interval is sub-second
1086 // to a few seconds, far below the u64 nanos ceiling (~584
1087 // years), so the cast can't truncate. See the field doc on
1088 // `StageUtilization::policy_degraded_nanos`.
1089 utilization
1090 .policy_degraded_nanos
1091 .fetch_add(elapsed.as_nanos() as u64, Ordering::Relaxed);
1092 }
1093 self.last_tick = now;
1094 }
1095
1096 /// Flush in-flight degraded accrual up to `now`, then reset to a
1097 /// fresh healthy-start logger. Called on a runtime durability-mode
1098 /// swap, which is a logger lifecycle boundary: without flushing
1099 /// first, the pre-swap degraded interval — on the gate-wait path the
1100 /// entire wedge — would be silently dropped. The new policy's actual
1101 /// degraded state is re-derived by the next `tick`, so the brief
1102 /// swap-to-next-tick window is attributed healthy; that residual is
1103 /// bounded by one tick interval, the counter's inherent granularity.
1104 pub(crate) fn reseed(&mut self, utilization: &StageUtilization, now: Instant) {
1105 let prev_state = self.pending_state;
1106 self.accrue(utilization, prev_state, now);
1107 *self = Self::new(now);
1108 }
1109
1110 /// Update the gauge + emit transition/heartbeat logs as needed.
1111 /// Cheap on the hot path: one atomic store, a few branches, one
1112 /// `Instant::duration_since`.
1113 pub(crate) fn tick(
1114 &mut self,
1115 policy: &Policy,
1116 utilization: &StageUtilization,
1117 degraded_now: bool,
1118 now: Instant,
1119 heartbeat_interval: Duration,
1120 ) {
1121 // Charge the just-elapsed interval to the state observed at the
1122 // *previous* tick. Snapshot it up front, before the flap-hold
1123 // bookkeeping below mutates `pending_state`, so accrual stays
1124 // correct even if that block is later reordered.
1125 let prev_state = self.pending_state;
1126 self.accrue(utilization, prev_state, now);
1127
1128 utilization
1129 .policy_degraded
1130 .store(degraded_now, Ordering::Relaxed);
1131
1132 if degraded_now != self.pending_state {
1133 // State changed — start a new hold window. Don't log
1134 // until / unless this new state stays long enough.
1135 self.pending_state = degraded_now;
1136 self.pending_since = now;
1137 self.pending_logged = false;
1138 return;
1139 }
1140
1141 // State held. If we haven't yet logged this streak's onset,
1142 // and it's been pending for at least the flap-hold time,
1143 // emit the transition message and mark logged.
1144 if !self.pending_logged && now.duration_since(self.pending_since) >= DEGRADED_FLAP_HOLD {
1145 if degraded_now {
1146 tracing::warn!(
1147 policy = %policy,
1148 "durability policy operating in degraded mode — fewer connected nodes than the target count, gate clamped to surviving cluster"
1149 );
1150 } else {
1151 tracing::info!(
1152 policy = %policy,
1153 "durability policy returned to target shape"
1154 );
1155 }
1156 self.pending_logged = true;
1157 self.last_log = Some(now);
1158 return;
1159 }
1160
1161 // Heartbeat re-emit while a degraded state persists.
1162 if degraded_now
1163 && self.pending_logged
1164 && self
1165 .last_log
1166 .is_none_or(|t| now.duration_since(t) >= heartbeat_interval)
1167 {
1168 tracing::warn!(
1169 policy = %policy,
1170 "durability policy still degraded — fewer connected nodes than the target count"
1171 );
1172 self.last_log = Some(now);
1173 }
1174 }
1175}
1176
1177/// Minimum persisted cursor across currently-connected replica slots.
1178/// Used for gate-bottleneck attribution and the journal-wait /
1179/// replica-wait histograms — *not* for durability decisions, which go
1180/// through [`evaluate_durability`].
1181///
1182/// Returns `u64::MAX` when no replica is connected, which makes
1183/// attribution always credit the journal — correct, because in
1184/// standalone mode the journal is the only path.
1185#[inline]
1186pub(crate) fn connected_persisted_min(
1187 metrics: Option<&ReplicationMetrics>,
1188 replica_active: Option<&[Arc<AtomicBool>; 2]>,
1189) -> u64 {
1190 let (Some(m), Some(active)) = (metrics, replica_active) else {
1191 return u64::MAX;
1192 };
1193 let mut min = u64::MAX;
1194 for (i, slot_active) in active.iter().enumerate() {
1195 if !slot_active.load(Ordering::Acquire) {
1196 continue;
1197 }
1198 let v = m.acked_sequence[i].load(Ordering::Acquire);
1199 if v < min {
1200 min = v;
1201 }
1202 }
1203 min
1204}
1205
1206/// Tracks per-cursor "first observed transition from below to >= needed"
1207/// inside the durability gate loop, to drive the journal-wait /
1208/// replica-wait histograms in the bench's tick-to-trade decomposition.
1209///
1210/// A sample is recorded only for cursors that were strictly below
1211/// `needed` at the loop's first observation. Cursors already past at
1212/// entry were not on the critical path for this batch, so attributing
1213/// "wait time" to them would inflate the metric with cursor-poll
1214/// observation timestamps that have nothing to do with how long the
1215/// stage actually held us up.
1216///
1217/// `now_ns` is taken as a parameter rather than read internally so
1218/// tests can supply deterministic timestamps. The caller's hot path
1219/// reads `trace::mono_trace_ns()` once per gate iteration and feeds it in.
1220#[cfg(feature = "tick-to-trade")]
1221pub(crate) struct GateCrossTracker {
1222 needed: u64,
1223 journal_crossed_ts: Option<trace::MonoTraceInstant>,
1224 replica_crossed_ts: Option<trace::MonoTraceInstant>,
1225 journal_was_below: bool,
1226 replica_was_below: bool,
1227 first: bool,
1228}
1229
1230#[cfg(feature = "tick-to-trade")]
1231impl GateCrossTracker {
1232 pub(crate) fn new(needed: u64) -> Self {
1233 Self {
1234 needed,
1235 journal_crossed_ts: None,
1236 replica_crossed_ts: None,
1237 journal_was_below: false,
1238 replica_was_below: false,
1239 first: true,
1240 }
1241 }
1242
1243 pub(crate) fn observe(
1244 &mut self,
1245 journal_pos: u64,
1246 repl_min: u64,
1247 now_ns: trace::MonoTraceInstant,
1248 ) {
1249 if self.first {
1250 self.journal_was_below = journal_pos < self.needed;
1251 self.replica_was_below = repl_min < self.needed;
1252 self.first = false;
1253 }
1254 if self.journal_was_below && self.journal_crossed_ts.is_none() && journal_pos >= self.needed
1255 {
1256 self.journal_crossed_ts = Some(now_ns);
1257 }
1258 if self.replica_was_below && self.replica_crossed_ts.is_none() && repl_min >= self.needed {
1259 self.replica_crossed_ts = Some(now_ns);
1260 }
1261 }
1262
1263 pub(crate) fn journal_crossed(&self) -> Option<trace::MonoTraceInstant> {
1264 self.journal_crossed_ts
1265 }
1266
1267 pub(crate) fn replica_crossed(&self) -> Option<trace::MonoTraceInstant> {
1268 self.replica_crossed_ts
1269 }
1270}
1271
1272/// Print busy/idle utilization for a pipeline stage on shutdown.
1273#[cfg(feature = "pipeline-stats")]
1274fn print_utilization(stage: &str, busy: u64, idle: u64) {
1275 let total = busy + idle;
1276 if total == 0 {
1277 tracing::info!(stage, "no iterations recorded");
1278 return;
1279 }
1280 let pct = (busy as f64 / total as f64) * 100.0;
1281 tracing::info!(
1282 stage,
1283 pct_busy = format_args!("{pct:.2}%"),
1284 busy,
1285 idle,
1286 total,
1287 "pipeline utilization",
1288 );
1289}
1290
1291#[cfg(test)]
1292mod tests {
1293 #[cfg(feature = "tick-to-trade")]
1294 use super::GateCrossTracker;
1295 use super::{DegradationLogger, WireSeq, connected_persisted_min, evaluate_durability};
1296 use crate::durability_policy::{Clause, Level, Policy};
1297 use crate::replication::ReplicationMetrics;
1298
1299 /// Build a [`Policy`] from a mini DSL: one or more
1300 /// `"<level>>=<count>"` clauses joined with `&&`. Test-only
1301 /// ergonomics — production builds policies via
1302 /// [`DurabilityMode::to_policy`].
1303 fn parse(s: &str) -> Result<Policy, String> {
1304 let mut clauses = Vec::new();
1305 for raw in s.split("&&") {
1306 let token = raw.trim();
1307 let (lvl, rhs) = token
1308 .split_once(">=")
1309 .ok_or_else(|| format!("clause `{token}` missing `>=`"))?;
1310 let level = match lvl.trim() {
1311 "persisted" => Level::Persisted,
1312 "in_memory" => Level::InMemory,
1313 other => return Err(format!("unknown level `{other}`")),
1314 };
1315 let count: u8 = rhs.trim().parse().map_err(|e| format!("bad count: {e}"))?;
1316 clauses.push(Clause { count, level });
1317 }
1318 Policy::new(clauses).map_err(|e| e.to_string())
1319 }
1320 use melin_transport_core::pipeline::StageUtilization;
1321 use std::sync::Arc;
1322 use std::sync::atomic::{AtomicBool, Ordering};
1323 use std::time::{Duration, Instant};
1324
1325 /// Build a `ReplicationMetrics` with both slots populated. Tests
1326 /// that need to simulate a disconnected slot use [`flags`] to mark
1327 /// it inactive — its cursors are then ignored regardless of value.
1328 fn metrics(slot0: (u64, u64), slot1: (u64, u64)) -> Arc<ReplicationMetrics> {
1329 let m = Arc::new(ReplicationMetrics::default());
1330 m.in_memory_sequence[0].store(slot0.0, Ordering::Relaxed);
1331 m.acked_sequence[0].store(slot0.1, Ordering::Relaxed);
1332 m.in_memory_sequence[1].store(slot1.0, Ordering::Relaxed);
1333 m.acked_sequence[1].store(slot1.1, Ordering::Relaxed);
1334 m
1335 }
1336
1337 /// Build a `[active; 2]` flags array.
1338 fn flags(slot0_active: bool, slot1_active: bool) -> [Arc<AtomicBool>; 2] {
1339 [
1340 Arc::new(AtomicBool::new(slot0_active)),
1341 Arc::new(AtomicBool::new(slot1_active)),
1342 ]
1343 }
1344
1345 /// Both replicas active — the common healthy-cluster case.
1346 fn both_active() -> [Arc<AtomicBool>; 2] {
1347 flags(true, true)
1348 }
1349
1350 // --- Standalone (no replicas wired) ---
1351
1352 #[test]
1353 fn standalone_persisted_one_gates_on_journal() {
1354 // No metrics → only the primary is in the view. `persisted>=1`
1355 // is satisfied by the primary alone at journal_pos.
1356 let p = parse("persisted>=1").unwrap();
1357 assert_eq!(
1358 evaluate_durability(&p, WireSeq::new(500), None, None).durable_pos,
1359 500
1360 );
1361 }
1362
1363 #[test]
1364 fn standalone_strict_persisted_two_never_opens() {
1365 // `persisted>=2` on a standalone primary stays at 0: the
1366 // operator asked for two copies and there is only one. The
1367 // policy surfaces as degraded so the operator sees the gate
1368 // is stalled because the cluster can't meet the policy.
1369 let p = parse("persisted>=2").unwrap();
1370 let r = evaluate_durability(&p, WireSeq::new(500), None, None);
1371 assert_eq!(r.durable_pos, 0);
1372 assert!(
1373 r.degraded,
1374 "policy structurally unsatisfiable on this shape → degraded",
1375 );
1376 }
1377
1378 // --- 2 replicas connected ---
1379
1380 #[test]
1381 fn quorum_both_replicas_ahead_of_journal() {
1382 // Both replicas persisted past journal. `persisted>=2` returns
1383 // the 2nd-largest persisted across {primary, slot0, slot1}.
1384 let p = parse("persisted>=2").unwrap();
1385 let m = metrics((100, 100), (120, 120));
1386 let a = both_active();
1387 assert_eq!(
1388 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
1389 100
1390 );
1391 }
1392
1393 #[test]
1394 fn quorum_journal_ahead_of_both_replicas() {
1395 // Journal at 500, replicas at 100/120. 2nd-largest persisted = 120.
1396 let p = parse("persisted>=2").unwrap();
1397 let m = metrics((100, 100), (120, 120));
1398 let a = both_active();
1399 assert_eq!(
1400 evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a)).durable_pos,
1401 120
1402 );
1403 }
1404
1405 #[test]
1406 fn quorum_journal_between_slow_and_fast_replica() {
1407 // {primary=150, slot0_persisted=50, slot1_persisted=200}.
1408 // 2nd-largest = 150 (primary itself).
1409 let p = parse("persisted>=2").unwrap();
1410 let m = metrics((50, 50), (200, 200));
1411 let a = both_active();
1412 assert_eq!(
1413 evaluate_durability(&p, WireSeq::new(150), Some(&m), Some(&a)).durable_pos,
1414 150
1415 );
1416 }
1417
1418 // --- Single replica connected ---
1419
1420 #[test]
1421 fn single_replica_strict_persisted_two_requires_both_survivors() {
1422 // Slot 0 connected, slot 1 disconnected. View = {primary, slot0}.
1423 // Strict `persisted>=2`: 2nd-largest of the 2-row view =
1424 // min(primary, slot0). Strictly stronger than legacy auto-
1425 // degrade-to-1-node in the same shape.
1426 let p = parse("persisted>=2").unwrap();
1427 let m = metrics((100, 100), (999, 999)); // slot 1 cursors ignored
1428 let a = flags(true, false);
1429 assert_eq!(
1430 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
1431 50
1432 );
1433 assert_eq!(
1434 evaluate_durability(&p, WireSeq::new(200), Some(&m), Some(&a)).durable_pos,
1435 100
1436 );
1437 }
1438
1439 #[test]
1440 fn single_replica_persisted_two_requires_both_survivors() {
1441 // 2-node view (primary + surviving replica). `persisted>=2` is
1442 // satisfiable; the gate opens at the slower of the two and the
1443 // policy is not degraded.
1444 let p = parse("persisted>=2").unwrap();
1445 let m = metrics((100, 100), (999, 999));
1446 let a = flags(true, false);
1447 let r = evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a));
1448 assert_eq!(r.durable_pos, 50);
1449 assert!(!r.degraded);
1450 }
1451
1452 #[test]
1453 fn both_replicas_disconnected_strict_stalls() {
1454 // View has only the primary. Strict `persisted>=2` cannot be
1455 // satisfied — operator opted out of degrade.
1456 let p = parse("persisted>=2").unwrap();
1457 let m = metrics((999, 999), (999, 999));
1458 let a = flags(false, false);
1459 assert_eq!(
1460 evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a)).durable_pos,
1461 0
1462 );
1463 }
1464
1465 #[test]
1466 fn both_replicas_disconnected_strict_stalls_and_flags_degraded() {
1467 // With `persisted>=2` and both replicas down, the cursor view
1468 // collapses to {primary}: the clause's count (=2) exceeds the
1469 // view size, so the gate stays at 0 and the policy flags
1470 // degraded. Note the matching stage's separate halt at
1471 // `replicas_connected==0` rejects new orders before they reach
1472 // the gate; this verifies the gate semantics in isolation.
1473 let p = parse("persisted>=2").unwrap();
1474 let m = metrics((999, 999), (999, 999));
1475 let a = flags(false, false);
1476 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
1477 assert_eq!(r.durable_pos, 0);
1478 assert!(r.degraded);
1479 }
1480
1481 // --- Mixed-level policies ---
1482
1483 #[test]
1484 fn persisted_one_and_in_memory_two() {
1485 // "Leader persists, plus one other node has it in memory" —
1486 // the cheap-but-non-zero durability target. Slot 0 has it in
1487 // memory, slot 1 disconnected.
1488 let p = parse("persisted>=1 && in_memory>=2").unwrap();
1489 // primary persisted=50, slot0 in_mem=80 / persisted=20.
1490 // persisted>=1: max(50, 20, 0) = 50.
1491 // in_memory>=2: primary in_mem=u64::MAX (always), slot0_eff=max(80, 20)=80,
1492 // slot1=0. 2nd-largest = 80.
1493 // min(50, 80) = 50.
1494 let m = metrics((80, 20), (999, 999));
1495 let a = flags(true, false);
1496 assert_eq!(
1497 evaluate_durability(&p, WireSeq::new(50), Some(&m), Some(&a)).durable_pos,
1498 50
1499 );
1500 }
1501
1502 // --- Edge: journal at 0 ---
1503
1504 #[test]
1505 fn journal_at_zero_with_replicas_persisted_one() {
1506 // Journal hasn't fsynced anything; both replicas have. With
1507 // `persisted>=1` the gate opens at the fastest replica.
1508 let p = parse("persisted>=1").unwrap();
1509 let m = metrics((100, 100), (200, 200));
1510 let a = both_active();
1511 assert_eq!(
1512 evaluate_durability(&p, WireSeq::new(0), Some(&m), Some(&a)).durable_pos,
1513 200
1514 );
1515 }
1516
1517 // --- connected_persisted_min — used for gate-bottleneck attribution ---
1518
1519 #[test]
1520 fn attribution_min_skips_disconnected_slots() {
1521 // Slot 1 disconnected via active flag.
1522 let m = metrics((150, 100), (999, 999));
1523 let a = flags(true, false);
1524 assert_eq!(connected_persisted_min(Some(&m), Some(&a)), 100);
1525 }
1526
1527 #[test]
1528 fn attribution_min_returns_max_when_standalone() {
1529 // No metrics wired → u64::MAX, which makes attribution always
1530 // credit the journal. Correct for a standalone deployment.
1531 assert_eq!(connected_persisted_min(None, None), u64::MAX);
1532 }
1533
1534 /// Fresh-cluster catch-up: a replica that handshakes at sequence
1535 /// 0 (the legitimate genesis case, not a stale-flag race) must be
1536 /// included in the cursor view with its zero cursors so the policy
1537 /// behaves the same way it would for a 1-replica deployment that
1538 /// has just produced its first batch. The disconnect-race
1539 /// mitigations (B1 seed-on-connect + B2 reorder) keep this from
1540 /// being conflated with the stale-flag-paired-with-zero-cursor
1541 /// case under normal cluster lifecycles.
1542 #[test]
1543 fn fresh_cluster_zero_cursors_included_in_view() {
1544 let p = parse("persisted>=2").unwrap();
1545 // Both replicas just handshook at seq 0, primary also at 0
1546 // (fresh cluster, no events yet). View = 3 nodes; the clause's
1547 // count (=2) is met by the view size, so the policy is not
1548 // degraded and the gate sits at the 2nd-largest persisted = 0.
1549 let m = metrics((0, 0), (0, 0));
1550 let a = both_active();
1551 let r = evaluate_durability(&p, WireSeq::new(0), Some(&m), Some(&a));
1552 assert_eq!(r.durable_pos, 0);
1553 assert!(
1554 !r.degraded,
1555 "all 3 nodes present, view meets clause target — should not flag degraded"
1556 );
1557 }
1558
1559 #[test]
1560 fn attribution_min_takes_smaller_when_both_connected() {
1561 let m = metrics((150, 100), (180, 80));
1562 let a = both_active();
1563 assert_eq!(connected_persisted_min(Some(&m), Some(&a)), 80);
1564 }
1565
1566 // -- Race-window regression tests --
1567 //
1568 // The replication senders fix two memory-ordering issues at the
1569 // active-flag transition points:
1570 //
1571 // B1 (`a84540a`): seed `metrics.{acked,in_memory}_sequence[i]`
1572 // to `handshake.last_sequence` BEFORE setting active_flag=true
1573 // on reconnect. Without this, the gate would observe (active=
1574 // true, cursor=0) for ~1 RTT after a replica catch-up completed,
1575 // freezing the gate on a degrade-friendly clause.
1576 //
1577 // B2 (`8888732`): zero `metrics.{acked,in_memory}_sequence[i]`
1578 // BEFORE setting active_flag=false on disconnect. Without this,
1579 // a weak-memory reader could observe (active=true, cursor=0)
1580 // for one iteration during the disconnect window.
1581 //
1582 // Both fixes are in the senders, but the gate's *behaviour* under
1583 // the race-window inputs is tested here. The intent is to lock in
1584 // the invariant: even under a hypothetical (active=true,cursor=0)
1585 // observation, the gate must not produce a spuriously-open answer
1586 // that would cause a client to be told "your event is durable"
1587 // when it isn't. Stalling-briefly is safe; opening-spuriously is
1588 // not.
1589
1590 #[test]
1591 fn race_b1_post_seed_gate_doesnt_freeze_on_reconnect() {
1592 // Post-B1-fix state: replica reconnected, cursors seeded to
1593 // `handshake.last_sequence` (480) before active flipped to
1594 // true. Primary kept moving and is at 500. The gate's view
1595 // is now [primary=500, slot=480]; the durable position dips
1596 // from 500 (primary alone, degraded) to 480 (both nodes).
1597 //
1598 // The dip is correct, not a bug: once a 2nd node is
1599 // connected, durability is bounded by the slower of the two.
1600 // Events 481-500 were already served as durable on primary
1601 // alone — they aren't unsent. New responses for seq>500 wait
1602 // until slot acks; we just don't freeze at 0.
1603 let p = parse("persisted>=2").unwrap();
1604 let m = metrics((480, 480), (999, 999));
1605 let a = flags(true, false);
1606 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
1607 assert_eq!(
1608 r.durable_pos, 480,
1609 "post-seed reconnect should produce a coherent gate position equal to the slower node, not freeze at 0"
1610 );
1611 }
1612
1613 #[test]
1614 fn race_b1_pre_seed_freeze_is_what_the_fix_avoids() {
1615 // Pre-B1-fix state: cursors at 0, active=true. The gate sees
1616 // [primary=500, slot=[0,0]] and 2nd-largest persisted = 0.
1617 // The gate WOULD freeze at 0. This test documents the bug
1618 // the seeding fix is designed to avoid; the senders ensure
1619 // this state is never observed in production.
1620 let p = parse("persisted>=2").unwrap();
1621 let m = metrics((0, 0), (999, 999));
1622 let a = flags(true, false);
1623 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
1624 assert_eq!(
1625 r.durable_pos, 0,
1626 "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"
1627 );
1628 }
1629
1630 #[test]
1631 fn race_b2_disconnect_window_doesnt_open_gate_spuriously() {
1632 // Simulates the B2 race window: a weak-memory reader observes
1633 // (active=true, cursor=0) for one iteration during the
1634 // disconnect transition. The slot legitimately has cursor=0
1635 // because the disconnect handler just zeroed the metrics.
1636 //
1637 // Critical invariant: the gate must NOT produce a higher
1638 // durable_pos than it would with the slot correctly excluded.
1639 // Specifically: with primary at 500, slot stale-zero-included,
1640 // the gate must not "see" the primary alone and open at 500
1641 // — that would let a client be told a seq is durable when
1642 // only the primary has it under a `persisted>=2` policy that
1643 // demands 2 nodes.
1644 let p = parse("persisted>=2").unwrap();
1645 let m = metrics((0, 0), (999, 999));
1646 let a = flags(true, false);
1647 let r = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a));
1648 // 2nd-largest persisted across {primary=500, slot=0} = 0.
1649 // Gate stalls. ✓
1650 assert_eq!(r.durable_pos, 0);
1651
1652 // Post-disconnect (active=false): view shrinks to {primary}.
1653 // `persisted>=2` is structurally unsatisfiable on a 1-node
1654 // view, so the gate stays at 0 AND surfaces degraded. The
1655 // matching stage's `replicas_connected==0` halt is what stops
1656 // accepting new orders; the gate side's job is just to keep
1657 // the existing in-flight orders stalled and the alert lit.
1658 let a_disconnected = flags(false, false);
1659 let r_after = evaluate_durability(&p, WireSeq::new(500), Some(&m), Some(&a_disconnected));
1660 assert_eq!(r_after.durable_pos, 0);
1661 assert!(
1662 r_after.degraded,
1663 "post-disconnect view of size 1 cannot meet persisted>=2 → degraded"
1664 );
1665 }
1666
1667 #[test]
1668 fn race_invariant_zero_cursor_never_opens_gate_above_slower_node() {
1669 // Property under both B1 and B2 race windows: for any slot
1670 // observed at cursor=0 with active=true, the gate cannot
1671 // produce a durable_pos that exceeds what an honest 2-node
1672 // evaluation would give. Spot-check a handful of primary
1673 // positions to lock the invariant.
1674 let p = parse("persisted>=2").unwrap();
1675 let m = metrics((0, 0), (999, 999));
1676 let a = flags(true, false);
1677 for primary_pos in [0, 1, 100, 500, 1_000_000_000_u64] {
1678 let r = evaluate_durability(&p, WireSeq::new(primary_pos), Some(&m), Some(&a));
1679 // 2nd-largest of {primary_pos, 0} = 0 for any primary > 0.
1680 // For primary_pos = 0, also 0. So always 0.
1681 assert_eq!(
1682 r.durable_pos, 0,
1683 "race-window observation must not open the gate above 0 for any primary position (got {} for primary_pos={primary_pos})",
1684 r.durable_pos
1685 );
1686 }
1687 }
1688
1689 // ------------------------------------------------------------------
1690 // GateCrossTracker — per-cursor "first transition from below to
1691 // crossed" inside the gate loop, used by the journal-wait /
1692 // replica-wait histograms.
1693 // ------------------------------------------------------------------
1694
1695 #[cfg(feature = "tick-to-trade")]
1696 #[test]
1697 fn gate_cross_tracker_records_journal_when_strictly_below() {
1698 // Journal starts at 5 (< 10), repl_min already at 100.
1699 // Journal crosses on the second observation. Replica was already
1700 // past at entry, so no replica sample.
1701 let mut t = GateCrossTracker::new(10);
1702 t.observe(5, 100, 1_000);
1703 t.observe(15, 100, 2_000);
1704 assert_eq!(t.journal_crossed(), Some(2_000));
1705 assert_eq!(t.replica_crossed(), None);
1706 }
1707
1708 #[cfg(feature = "tick-to-trade")]
1709 #[test]
1710 fn gate_cross_tracker_records_replica_when_strictly_below() {
1711 // Mirror image: journal already past, replica below at entry.
1712 let mut t = GateCrossTracker::new(10);
1713 t.observe(50, 5, 1_000);
1714 t.observe(50, 12, 2_000);
1715 assert_eq!(t.journal_crossed(), None);
1716 assert_eq!(t.replica_crossed(), Some(2_000));
1717 }
1718
1719 #[cfg(feature = "tick-to-trade")]
1720 #[test]
1721 fn gate_cross_tracker_records_both_when_both_below() {
1722 // Both below at entry, both cross independently.
1723 let mut t = GateCrossTracker::new(100);
1724 t.observe(50, 60, 1_000); // both below
1725 t.observe(105, 60, 2_000); // journal crosses
1726 t.observe(105, 110, 3_000); // replica crosses
1727 assert_eq!(t.journal_crossed(), Some(2_000));
1728 assert_eq!(t.replica_crossed(), Some(3_000));
1729 }
1730
1731 #[cfg(feature = "tick-to-trade")]
1732 #[test]
1733 fn gate_cross_tracker_skips_cursor_already_past_at_entry() {
1734 // Both cursors already >= needed at first observation —
1735 // neither was on the critical path. No samples.
1736 let mut t = GateCrossTracker::new(10);
1737 t.observe(50, 100, 1_000);
1738 // Even later observations don't backfill: was_below is sticky.
1739 t.observe(60, 110, 2_000);
1740 assert_eq!(t.journal_crossed(), None);
1741 assert_eq!(t.replica_crossed(), None);
1742 }
1743
1744 #[cfg(feature = "tick-to-trade")]
1745 #[test]
1746 fn gate_cross_tracker_first_observation_only_for_cross_decision() {
1747 // A cursor that goes back below `needed` after first iteration
1748 // (impossible in practice — cursors are monotonic — but we
1749 // verify the first-iteration snapshot is what gates the
1750 // sample). Journal: 50 < 10 false → was_below=false → no sample.
1751 let mut t = GateCrossTracker::new(10);
1752 t.observe(50, 5, 1_000); // journal already past, replica below
1753 t.observe(20, 12, 2_000); // both >= needed now
1754 // Journal: was_below=false at entry → still no sample.
1755 assert_eq!(t.journal_crossed(), None);
1756 // Replica: was_below=true at entry, crosses on iter 2 → sample.
1757 assert_eq!(t.replica_crossed(), Some(2_000));
1758 }
1759
1760 #[cfg(feature = "tick-to-trade")]
1761 #[test]
1762 fn gate_cross_tracker_holds_first_cross_only() {
1763 // Once a cross is recorded, later observations don't
1764 // overwrite — the metric is "when did it first cross", not
1765 // "when was it last below".
1766 let mut t = GateCrossTracker::new(10);
1767 t.observe(5, 100, 1_000);
1768 t.observe(15, 100, 2_000); // first cross
1769 t.observe(25, 100, 3_000); // would otherwise re-record
1770 assert_eq!(t.journal_crossed(), Some(2_000));
1771 }
1772
1773 // -- DegradationLogger flap-suppression --
1774 //
1775 // The logger gates transition logs on a sustained-state hold so a
1776 // replica flapping at sub-second cadence doesn't spam the journal.
1777 // These tests don't observe the logs themselves (tracing is
1778 // process-global and brittle to capture in unit tests); they
1779 // assert the underlying state machine via the `policy_degraded`
1780 // gauge, which the logger updates on every tick regardless of
1781 // log emission.
1782
1783 fn logger_test_policy() -> crate::durability_policy::Policy {
1784 parse("persisted>=2").unwrap()
1785 }
1786
1787 /// Tick the logger N times at `step` intervals, alternating
1788 /// `degraded` per call. Returns the gauge value after the last
1789 /// tick — useful for asserting that flap cycles don't leak the
1790 /// AtomicBool into a wrong terminal state.
1791 fn drive_logger(
1792 logger: &mut DegradationLogger,
1793 utilization: &StageUtilization,
1794 policy: &crate::durability_policy::Policy,
1795 start: Instant,
1796 states: &[bool],
1797 step: Duration,
1798 ) -> bool {
1799 for (i, &state) in states.iter().enumerate() {
1800 let now = start + step.checked_mul(i as u32).unwrap_or(Duration::ZERO);
1801 logger.tick(policy, utilization, state, now, Duration::from_secs(5));
1802 }
1803 utilization.policy_degraded.load(Ordering::Relaxed)
1804 }
1805
1806 #[test]
1807 fn logger_gauge_tracks_state_immediately() {
1808 // The /healthz gauge reflects the *latest* state on every
1809 // tick — this is what dashboards / alerts read. Sustained-
1810 // state gating only affects the warn/info log emission.
1811 let p = logger_test_policy();
1812 let utilization = StageUtilization::new();
1813 let now = Instant::now();
1814 let mut logger = DegradationLogger::new(now);
1815
1816 logger.tick(&p, &utilization, true, now, Duration::from_secs(5));
1817 assert!(utilization.policy_degraded.load(Ordering::Relaxed));
1818
1819 logger.tick(
1820 &p,
1821 &utilization,
1822 false,
1823 now + Duration::from_millis(50),
1824 Duration::from_secs(5),
1825 );
1826 assert!(!utilization.policy_degraded.load(Ordering::Relaxed));
1827 }
1828
1829 #[test]
1830 fn logger_starting_degraded_marks_initial_state_logged() {
1831 // `new_starting_degraded` emits the startup warn and treats
1832 // the state as already-logged so the next tick at the same
1833 // cluster shape doesn't re-emit instantly. The gauge starts
1834 // at 1.
1835 let p = logger_test_policy();
1836 let utilization = StageUtilization::new();
1837 let now = Instant::now();
1838 let mut logger = DegradationLogger::new_starting_degraded(now, &p);
1839 // The logger doesn't write the gauge from the constructor —
1840 // first tick does. Tick at the same state to settle the
1841 // gauge. No new log line should fire (state hasn't changed).
1842 logger.tick(
1843 &p,
1844 &utilization,
1845 true,
1846 now + Duration::from_millis(10),
1847 Duration::from_secs(5),
1848 );
1849 assert!(utilization.policy_degraded.load(Ordering::Relaxed));
1850 }
1851
1852 #[test]
1853 fn logger_accumulates_degraded_seconds_only_while_degraded() {
1854 // The `policy_degraded_nanos` counter must advance by exactly
1855 // the wall-clock time spent in the degraded state and stay flat
1856 // while healthy. Each tick attributes the interval since the
1857 // previous tick to the state observed at that previous tick.
1858 let p = logger_test_policy();
1859 let utilization = StageUtilization::new();
1860 let start = Instant::now();
1861 let mut logger = DegradationLogger::new(start);
1862 let sec = Duration::from_secs(1);
1863
1864 // t0: healthy -> degraded. The zero-length interval before the
1865 // transition is attributed to the healthy start: no accrual.
1866 logger.tick(&p, &utilization, true, start, Duration::from_secs(5));
1867 assert_eq!(utilization.policy_degraded_nanos.load(Ordering::Relaxed), 0);
1868
1869 // t0..t1 spent degraded -> +1s.
1870 logger.tick(&p, &utilization, true, start + sec, Duration::from_secs(5));
1871 // t1..t2 still degraded, then flips healthy at the tick -> +1s.
1872 logger.tick(
1873 &p,
1874 &utilization,
1875 false,
1876 start + 2 * sec,
1877 Duration::from_secs(5),
1878 );
1879 assert_eq!(
1880 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1881 2 * sec.as_nanos() as u64
1882 );
1883
1884 // t2..t3 spent healthy -> counter holds flat.
1885 logger.tick(
1886 &p,
1887 &utilization,
1888 false,
1889 start + 3 * sec,
1890 Duration::from_secs(5),
1891 );
1892 assert_eq!(
1893 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1894 2 * sec.as_nanos() as u64
1895 );
1896 }
1897
1898 #[test]
1899 fn logger_starting_degraded_accrues_from_construction() {
1900 // A primary that boots already-degraded (e.g. `hybrid` with no
1901 // replica yet) must accrue from construction, not from the first
1902 // observed transition — `new_starting_degraded` seeds the
1903 // degraded state so the first tick's interval counts.
1904 let p = logger_test_policy();
1905 let utilization = StageUtilization::new();
1906 let start = Instant::now();
1907 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
1908
1909 logger.tick(
1910 &p,
1911 &utilization,
1912 true,
1913 start + Duration::from_secs(1),
1914 Duration::from_secs(5),
1915 );
1916 assert_eq!(
1917 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1918 Duration::from_secs(1).as_nanos() as u64
1919 );
1920 }
1921
1922 #[test]
1923 fn logger_reseed_flushes_in_flight_degraded_accrual() {
1924 // A runtime mode swap re-seeds the logger. On the gate-wait path
1925 // the swap can land after many seconds of wedged-degraded time
1926 // with no intervening tick, so `reseed` must flush that interval
1927 // before resetting — otherwise the whole wedge is silently lost,
1928 // which is exactly the incident the metric exists to measure.
1929 let p = logger_test_policy();
1930 let utilization = StageUtilization::new();
1931 let start = Instant::now();
1932 let sec = Duration::from_secs(1);
1933
1934 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
1935 logger.tick(&p, &utilization, true, start, Duration::from_secs(5));
1936 assert_eq!(utilization.policy_degraded_nanos.load(Ordering::Relaxed), 0);
1937
1938 // 30s wedged-degraded with no tick (frozen spin), then swap.
1939 logger.reseed(&utilization, start + 30 * sec);
1940 assert_eq!(
1941 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1942 30 * sec.as_nanos() as u64
1943 );
1944
1945 // Post-reseed the logger is healthy-start; a healthy interval
1946 // does not accrue, and `last_tick` was rebased to the swap so
1947 // the next interval isn't double-counted.
1948 logger.tick(
1949 &p,
1950 &utilization,
1951 false,
1952 start + 31 * sec,
1953 Duration::from_secs(5),
1954 );
1955 assert_eq!(
1956 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1957 30 * sec.as_nanos() as u64
1958 );
1959 }
1960
1961 #[test]
1962 fn logger_starting_degraded_then_first_tick_healthy_counts_construction_interval() {
1963 // `new_starting_degraded` seeds the degraded state, so the
1964 // construction→first-tick interval is attributed degraded even
1965 // when the first observed state is already healthy (the cluster
1966 // recovered before the first tick). Locks this intentional edge.
1967 let p = logger_test_policy();
1968 let utilization = StageUtilization::new();
1969 let start = Instant::now();
1970 let mut logger = DegradationLogger::new_starting_degraded(start, &p);
1971
1972 logger.tick(
1973 &p,
1974 &utilization,
1975 false,
1976 start + Duration::from_secs(2),
1977 Duration::from_secs(5),
1978 );
1979 assert_eq!(
1980 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
1981 Duration::from_secs(2).as_nanos() as u64
1982 );
1983 }
1984
1985 #[test]
1986 fn logger_counter_matches_total_degraded_time_across_flaps() {
1987 // The cumulative counter must equal exactly the wall time spent
1988 // in degraded states across a flap sequence — the guarantee
1989 // `rate(...degraded_seconds_total)` dashboards depend on.
1990 let p = logger_test_policy();
1991 let utilization = StageUtilization::new();
1992 let start = Instant::now();
1993 let step = Duration::from_millis(500);
1994 let mut logger = DegradationLogger::new(start);
1995
1996 // State observed at tick i (fired at start + i*step). The state
1997 // set at tick i holds over [tick i, tick i+1], so degraded wall
1998 // time = the spans where the *prior* tick's state was true:
1999 // [t1,t2], [t2,t3], [t4,t5] = 3 * step.
2000 let states = [false, true, true, false, true, false];
2001 for (i, &s) in states.iter().enumerate() {
2002 logger.tick(
2003 &p,
2004 &utilization,
2005 s,
2006 start + step * i as u32,
2007 Duration::from_secs(5),
2008 );
2009 }
2010
2011 assert_eq!(
2012 utilization.policy_degraded_nanos.load(Ordering::Relaxed),
2013 (3 * step).as_nanos() as u64
2014 );
2015 }
2016
2017 #[test]
2018 fn logger_handles_rapid_flap_without_panic() {
2019 // Drive the logger through 100 alternating flips at 100ms
2020 // each (faster than the 1s flap-hold). The state machine
2021 // must remain coherent — no panics, gauge tracks final
2022 // state, and `pending_logged` doesn't get stuck.
2023 let p = logger_test_policy();
2024 let utilization = StageUtilization::new();
2025 let now = Instant::now();
2026 let mut logger = DegradationLogger::new(now);
2027 let states: Vec<bool> = (0..100u32).map(|i| i.is_multiple_of(2)).collect();
2028 let final_state = drive_logger(
2029 &mut logger,
2030 &utilization,
2031 &p,
2032 now,
2033 &states,
2034 Duration::from_millis(100),
2035 );
2036 // 100 states starting at i=0 → final state is i=99 → odd → false.
2037 assert!(!final_state);
2038 }
2039
2040 #[test]
2041 fn logger_sustained_degraded_eventually_settles() {
2042 // After a sustained-true state, the logger should be in the
2043 // "logged the onset" mode. Drive 5 ticks of degraded=true at
2044 // 500ms intervals — total 2s, well past the 1s flap-hold.
2045 // Last tick should leave gauge=1 and the heartbeat re-emit
2046 // window primed (last_log set).
2047 let p = logger_test_policy();
2048 let utilization = StageUtilization::new();
2049 let now = Instant::now();
2050 let mut logger = DegradationLogger::new(now);
2051 let final_state = drive_logger(
2052 &mut logger,
2053 &utilization,
2054 &p,
2055 now,
2056 &[true; 5],
2057 Duration::from_millis(500),
2058 );
2059 assert!(final_state);
2060 }
2061
2062 #[test]
2063 fn logger_recovery_to_healthy_settles_gauge() {
2064 // Sustained degraded → sustained healthy. Gauge should end at 0.
2065 let p = logger_test_policy();
2066 let utilization = StageUtilization::new();
2067 let now = Instant::now();
2068 let mut logger = DegradationLogger::new_starting_degraded(now, &p);
2069 let mut states = vec![true; 5]; // 2.5s degraded
2070 states.extend(vec![false; 5]); // 2.5s healthy
2071 let final_state = drive_logger(
2072 &mut logger,
2073 &utilization,
2074 &p,
2075 now,
2076 &states,
2077 Duration::from_millis(500),
2078 );
2079 assert!(!final_state);
2080 }
2081}