Skip to main content

ftui_runtime/
effect_system.rs

1#![forbid(unsafe_code)]
2
3//! Effect system observability and Cx-aware execution helpers.
4//!
5//! This module provides:
6//!
7//! - **Cx-aware task execution**: `run_task_with_cx` wraps a closure with
8//!   a `Cx` context for cooperative cancellation and deadline enforcement.
9//! - **Tracing spans**: `effect.command` and `effect.subscription` spans
10//!   with structured fields for observability dashboards.
11//! - **Metrics counters**: `effects_executed_total` (by type) and
12//!   `effect_duration_us` histogram approximation.
13//!
14//! # bd-37a.6: Command/Subscription effect system with Cx capability threading
15
16use std::sync::atomic::{AtomicU64, Ordering};
17use web_time::Instant;
18
19// ---------------------------------------------------------------------------
20// Monotonic counters
21// ---------------------------------------------------------------------------
22
23static EFFECTS_COMMAND_TOTAL: AtomicU64 = AtomicU64::new(0);
24static EFFECTS_SUBSCRIPTION_TOTAL: AtomicU64 = AtomicU64::new(0);
25static EFFECTS_QUEUE_ENQUEUED: AtomicU64 = AtomicU64::new(0);
26static EFFECTS_QUEUE_PROCESSED: AtomicU64 = AtomicU64::new(0);
27static EFFECTS_QUEUE_DROPPED: AtomicU64 = AtomicU64::new(0);
28static EFFECTS_QUEUE_HIGH_WATER: AtomicU64 = AtomicU64::new(0);
29
30/// Total command effects executed (monotonic counter).
31#[must_use]
32pub fn effects_command_total() -> u64 {
33    EFFECTS_COMMAND_TOTAL.load(Ordering::Relaxed)
34}
35
36/// Total subscription effects started (monotonic counter).
37#[must_use]
38pub fn effects_subscription_total() -> u64 {
39    EFFECTS_SUBSCRIPTION_TOTAL.load(Ordering::Relaxed)
40}
41
42/// Combined total of all effects executed.
43#[must_use]
44pub fn effects_executed_total() -> u64 {
45    effects_command_total() + effects_subscription_total()
46}
47
48// ---------------------------------------------------------------------------
49// Queue telemetry (bd-2zd0a)
50// ---------------------------------------------------------------------------
51
52/// Total tasks enqueued to the effect queue (monotonic counter).
53#[must_use]
54pub fn effects_queue_enqueued() -> u64 {
55    EFFECTS_QUEUE_ENQUEUED.load(Ordering::Relaxed)
56}
57
58/// Total tasks processed by the effect queue (monotonic counter).
59#[must_use]
60pub fn effects_queue_processed() -> u64 {
61    EFFECTS_QUEUE_PROCESSED.load(Ordering::Relaxed)
62}
63
64/// Total tasks dropped due to backpressure or shutdown (monotonic counter).
65#[must_use]
66pub fn effects_queue_dropped() -> u64 {
67    EFFECTS_QUEUE_DROPPED.load(Ordering::Relaxed)
68}
69
70/// High-water mark: maximum queue depth observed (ratchet — only increases).
71#[must_use]
72pub fn effects_queue_high_water() -> u64 {
73    EFFECTS_QUEUE_HIGH_WATER.load(Ordering::Relaxed)
74}
75
76/// Record a task enqueue, updating counters and high-water mark.
77pub fn record_queue_enqueue(current_depth: u64) {
78    EFFECTS_QUEUE_ENQUEUED.fetch_add(1, Ordering::Relaxed);
79    // Ratchet high-water mark upward.
80    let mut prev = EFFECTS_QUEUE_HIGH_WATER.load(Ordering::Relaxed);
81    while current_depth > prev {
82        match EFFECTS_QUEUE_HIGH_WATER.compare_exchange_weak(
83            prev,
84            current_depth,
85            Ordering::Relaxed,
86            Ordering::Relaxed,
87        ) {
88            Ok(_) => break,
89            Err(actual) => prev = actual,
90        }
91    }
92}
93
94/// Record a task processed by the effect queue.
95pub fn record_queue_processed() {
96    EFFECTS_QUEUE_PROCESSED.fetch_add(1, Ordering::Relaxed);
97}
98
99/// Record a task dropped due to backpressure or shutdown.
100pub fn record_queue_drop(reason: &str) {
101    EFFECTS_QUEUE_DROPPED.fetch_add(1, Ordering::Relaxed);
102    tracing::warn!(
103        target: "ftui.effect",
104        reason = reason,
105        monotonic.counter.effects_queue_dropped_total = 1_u64,
106        "effect queue task dropped"
107    );
108}
109
110/// Snapshot of queue telemetry for operator dashboards.
111#[derive(Debug, Clone, Copy, PartialEq, Eq)]
112pub struct QueueTelemetry {
113    /// Total tasks enqueued (monotonic).
114    pub enqueued: u64,
115    /// Total tasks processed (monotonic).
116    pub processed: u64,
117    /// Total tasks dropped (monotonic).
118    pub dropped: u64,
119    /// Maximum queue depth observed.
120    pub high_water: u64,
121    /// Current in-flight: enqueued - processed. Drops are NOT subtracted:
122    /// every drop path rejects a task *before* it is counted as enqueued, so
123    /// subtracting `dropped` would permanently understate the backlog by the
124    /// cumulative drop total.
125    pub in_flight: u64,
126}
127
128/// Snapshot the current queue telemetry counters.
129///
130/// This is a lock-free, best-effort snapshot: the counters are loaded
131/// independently, so under concurrent enqueue/process the derived `in_flight`
132/// may transiently disagree with any single instantaneous state. The skew is
133/// bounded and one-directional — `enqueued` is loaded first (the oldest value)
134/// and `processed` last (the newest), so `in_flight` can only *under*estimate
135/// the true backlog (floored at 0 by the saturating subtraction), never
136/// overestimate it. That is the safe bias for the consumers (load-governor
137/// pressure classification, backpressure), which read it per-frame and recover
138/// on the next interval; do not treat it as an exact, linearizable count.
139///
140/// `dropped` is deliberately NOT subtracted from `in_flight`: drop paths
141/// reject a task before it is ever counted as enqueued, so subtracting it
142/// would double-penalize and permanently understate the backlog after any
143/// overload episode.
144#[must_use]
145pub fn queue_telemetry() -> QueueTelemetry {
146    let enqueued = effects_queue_enqueued();
147    let processed = effects_queue_processed();
148    let dropped = effects_queue_dropped();
149    let in_flight = enqueued.saturating_sub(processed);
150    QueueTelemetry {
151        enqueued,
152        processed,
153        dropped,
154        high_water: effects_queue_high_water(),
155        in_flight,
156    }
157}
158
159// ---------------------------------------------------------------------------
160// Runtime dynamics instrumentation (bd-4flji)
161//
162// These metrics track the leading indicators of user-visible pain:
163// subscription churn, shutdown latency, and reconcile frequency.
164// ---------------------------------------------------------------------------
165
166static SUBSCRIPTION_STARTS_TOTAL: AtomicU64 = AtomicU64::new(0);
167static SUBSCRIPTION_STOPS_TOTAL: AtomicU64 = AtomicU64::new(0);
168static SUBSCRIPTION_PANICS_TOTAL: AtomicU64 = AtomicU64::new(0);
169static RECONCILE_COUNT: AtomicU64 = AtomicU64::new(0);
170static RECONCILE_DURATION_US_TOTAL: AtomicU64 = AtomicU64::new(0);
171static SHUTDOWN_DURATION_US_LAST: AtomicU64 = AtomicU64::new(0);
172static SHUTDOWN_TIMED_OUT_TOTAL: AtomicU64 = AtomicU64::new(0);
173
174/// Total subscription starts (monotonic counter).
175#[must_use]
176pub fn subscription_starts_total() -> u64 {
177    SUBSCRIPTION_STARTS_TOTAL.load(Ordering::Relaxed)
178}
179
180/// Total subscription stops (monotonic counter).
181#[must_use]
182pub fn subscription_stops_total() -> u64 {
183    SUBSCRIPTION_STOPS_TOTAL.load(Ordering::Relaxed)
184}
185
186/// Total subscription panics caught (monotonic counter).
187#[must_use]
188pub fn subscription_panics_total() -> u64 {
189    SUBSCRIPTION_PANICS_TOTAL.load(Ordering::Relaxed)
190}
191
192/// Total reconcile operations (monotonic counter).
193#[must_use]
194pub fn reconcile_count() -> u64 {
195    RECONCILE_COUNT.load(Ordering::Relaxed)
196}
197
198/// Cumulative reconcile duration in microseconds.
199#[must_use]
200pub fn reconcile_duration_us_total() -> u64 {
201    RECONCILE_DURATION_US_TOTAL.load(Ordering::Relaxed)
202}
203
204/// Most recent shutdown duration in microseconds (0 = no shutdown yet).
205#[must_use]
206pub fn shutdown_duration_us_last() -> u64 {
207    SHUTDOWN_DURATION_US_LAST.load(Ordering::Relaxed)
208}
209
210/// Total subscription join timeouts during shutdown (monotonic counter).
211#[must_use]
212pub fn shutdown_timed_out_total() -> u64 {
213    SHUTDOWN_TIMED_OUT_TOTAL.load(Ordering::Relaxed)
214}
215
216/// Record a subscription start event.
217pub fn record_dynamics_sub_start() {
218    SUBSCRIPTION_STARTS_TOTAL.fetch_add(1, Ordering::Relaxed);
219}
220
221/// Record a subscription stop event.
222pub fn record_dynamics_sub_stop() {
223    SUBSCRIPTION_STOPS_TOTAL.fetch_add(1, Ordering::Relaxed);
224}
225
226/// Record a subscription panic event.
227pub fn record_dynamics_sub_panic() {
228    SUBSCRIPTION_PANICS_TOTAL.fetch_add(1, Ordering::Relaxed);
229}
230
231/// Record a reconcile operation with its duration.
232pub fn record_dynamics_reconcile(duration_us: u64) {
233    RECONCILE_COUNT.fetch_add(1, Ordering::Relaxed);
234    RECONCILE_DURATION_US_TOTAL.fetch_add(duration_us, Ordering::Relaxed);
235}
236
237/// Record a shutdown completion with its duration and timeout count.
238pub fn record_dynamics_shutdown(duration_us: u64, timed_out: u64) {
239    SHUTDOWN_DURATION_US_LAST.store(duration_us, Ordering::Relaxed);
240    SHUTDOWN_TIMED_OUT_TOTAL.fetch_add(timed_out, Ordering::Relaxed);
241}
242
243/// Snapshot of runtime dynamics for operator dashboards and performance analysis.
244#[derive(Debug, Clone, Copy, PartialEq, Eq)]
245pub struct RuntimeDynamics {
246    /// Total subscription starts.
247    pub sub_starts: u64,
248    /// Total subscription stops.
249    pub sub_stops: u64,
250    /// Total subscription panics caught.
251    pub sub_panics: u64,
252    /// Current subscription churn: starts - stops.
253    pub sub_active_estimate: u64,
254    /// Total reconcile operations.
255    pub reconciles: u64,
256    /// Average reconcile duration in microseconds (0 if no reconciles yet).
257    pub reconcile_avg_us: u64,
258    /// Most recent shutdown duration in microseconds.
259    pub shutdown_last_us: u64,
260    /// Total join timeouts during shutdowns.
261    pub shutdown_timeouts: u64,
262}
263
264/// Snapshot the current runtime dynamics counters.
265#[must_use]
266pub fn runtime_dynamics() -> RuntimeDynamics {
267    let sub_starts = subscription_starts_total();
268    let sub_stops = subscription_stops_total();
269    let reconciles = reconcile_count();
270    let reconcile_total_us = reconcile_duration_us_total();
271    RuntimeDynamics {
272        sub_starts,
273        sub_stops,
274        sub_panics: subscription_panics_total(),
275        sub_active_estimate: sub_starts.saturating_sub(sub_stops),
276        reconciles,
277        reconcile_avg_us: reconcile_total_us.checked_div(reconciles).unwrap_or(0),
278        shutdown_last_us: shutdown_duration_us_last(),
279        shutdown_timeouts: shutdown_timed_out_total(),
280    }
281}
282
283// ---------------------------------------------------------------------------
284// Command effect instrumentation
285// ---------------------------------------------------------------------------
286
287/// Execute a command effect with tracing instrumentation.
288///
289/// Wraps command execution with an `effect.command` span recording
290/// `command_type`, `duration_us`, and `result`.
291pub fn trace_command_effect<F, R>(command_type: &str, f: F) -> R
292where
293    F: FnOnce() -> R,
294{
295    EFFECTS_COMMAND_TOTAL.fetch_add(1, Ordering::Relaxed);
296
297    let start = Instant::now();
298    let _span = tracing::debug_span!(
299        "effect.command",
300        command_type = %command_type,
301        duration_us = tracing::field::Empty,
302        result = tracing::field::Empty,
303    )
304    .entered();
305
306    tracing::debug!(
307        target: "ftui.effect",
308        command_type = %command_type,
309        "command effect started"
310    );
311
312    let result = f();
313    let duration_us = start.elapsed().as_micros() as u64;
314
315    tracing::debug!(
316        target: "ftui.effect",
317        command_type = %command_type,
318        duration_us = duration_us,
319        effect_duration_us = duration_us,
320        "command effect completed"
321    );
322
323    result
324}
325
326/// Record a command effect execution without wrapping (for inline instrumentation).
327pub fn record_command_effect(command_type: &str, duration_us: u64) {
328    EFFECTS_COMMAND_TOTAL.fetch_add(1, Ordering::Relaxed);
329
330    let _span = tracing::debug_span!(
331        "effect.command",
332        command_type = %command_type,
333        duration_us = duration_us,
334        result = "ok",
335    )
336    .entered();
337
338    tracing::debug!(
339        target: "ftui.effect",
340        command_type = %command_type,
341        duration_us = duration_us,
342        effect_duration_us = duration_us,
343        "command effect recorded"
344    );
345}
346
347// ---------------------------------------------------------------------------
348// Subscription effect instrumentation
349// ---------------------------------------------------------------------------
350
351/// Record a subscription lifecycle event.
352pub fn record_subscription_start(sub_type: &str, sub_id: u64) {
353    EFFECTS_SUBSCRIPTION_TOTAL.fetch_add(1, Ordering::Relaxed);
354
355    let _span = tracing::debug_span!(
356        "effect.subscription",
357        sub_type = %sub_type,
358        event_count = 0u64,
359        active = true,
360    )
361    .entered();
362
363    tracing::debug!(
364        target: "ftui.effect",
365        sub_type = %sub_type,
366        sub_id = sub_id,
367        active = true,
368        "subscription started"
369    );
370}
371
372/// Record a subscription stop event.
373pub fn record_subscription_stop(sub_type: &str, sub_id: u64, event_count: u64) {
374    let _span = tracing::debug_span!(
375        "effect.subscription",
376        sub_type = %sub_type,
377        event_count = event_count,
378        active = false,
379    )
380    .entered();
381
382    tracing::debug!(
383        target: "ftui.effect",
384        sub_type = %sub_type,
385        sub_id = sub_id,
386        event_count = event_count,
387        active = false,
388        "subscription stopped"
389    );
390}
391
392/// Record an effect timeout warning.
393pub fn warn_effect_timeout(effect_type: &str, deadline_us: u64) {
394    tracing::warn!(
395        target: "ftui.effect",
396        effect_type = %effect_type,
397        deadline_us = deadline_us,
398        "effect timeout exceeded deadline"
399    );
400}
401
402/// Record an effect panic error.
403pub fn error_effect_panic(effect_type: &str, panic_msg: &str) {
404    tracing::error!(
405        target: "ftui.effect",
406        effect_type = %effect_type,
407        panic_msg = %panic_msg,
408        "effect panicked during execution"
409    );
410}
411
412// ============================================================================
413// Tests
414// ============================================================================
415
416#[cfg(test)]
417mod tests {
418    use super::*;
419    use std::collections::HashMap;
420    use std::sync::{Arc, Mutex};
421    use tracing_subscriber::layer::SubscriberExt;
422    use tracing_subscriber::registry::LookupSpan;
423
424    // Tracing capture infrastructure
425    #[derive(Debug, Clone)]
426    #[allow(dead_code)]
427    struct CapturedSpan {
428        name: String,
429        fields: HashMap<String, String>,
430    }
431
432    #[derive(Debug, Clone)]
433    #[allow(dead_code)]
434    struct CapturedEvent {
435        level: tracing::Level,
436        target: String,
437        fields: HashMap<String, String>,
438    }
439
440    struct SpanCapture {
441        spans: Arc<Mutex<Vec<CapturedSpan>>>,
442        events: Arc<Mutex<Vec<CapturedEvent>>>,
443    }
444
445    impl SpanCapture {
446        fn new() -> (Self, CaptureHandle) {
447            let spans = Arc::new(Mutex::new(Vec::new()));
448            let events = Arc::new(Mutex::new(Vec::new()));
449            let handle = CaptureHandle {
450                spans: spans.clone(),
451                events: events.clone(),
452            };
453            (Self { spans, events }, handle)
454        }
455    }
456
457    struct CaptureHandle {
458        spans: Arc<Mutex<Vec<CapturedSpan>>>,
459        events: Arc<Mutex<Vec<CapturedEvent>>>,
460    }
461
462    impl CaptureHandle {
463        fn spans(&self) -> Vec<CapturedSpan> {
464            self.spans.lock().unwrap().clone()
465        }
466
467        fn events(&self) -> Vec<CapturedEvent> {
468            self.events.lock().unwrap().clone()
469        }
470    }
471
472    struct FieldVisitor(Vec<(String, String)>);
473
474    impl tracing::field::Visit for FieldVisitor {
475        fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
476            self.0
477                .push((field.name().to_string(), format!("{value:?}")));
478        }
479        fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
480            self.0.push((field.name().to_string(), value.to_string()));
481        }
482        fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
483            self.0.push((field.name().to_string(), value.to_string()));
484        }
485        fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
486            self.0.push((field.name().to_string(), value.to_string()));
487        }
488        fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
489            self.0.push((field.name().to_string(), value.to_string()));
490        }
491    }
492
493    impl<S> tracing_subscriber::Layer<S> for SpanCapture
494    where
495        S: tracing::Subscriber + for<'a> LookupSpan<'a>,
496    {
497        fn on_new_span(
498            &self,
499            attrs: &tracing::span::Attributes<'_>,
500            _id: &tracing::span::Id,
501            _ctx: tracing_subscriber::layer::Context<'_, S>,
502        ) {
503            let mut visitor = FieldVisitor(Vec::new());
504            attrs.record(&mut visitor);
505            let mut fields: HashMap<String, String> = visitor.0.into_iter().collect();
506            for field in attrs.metadata().fields() {
507                fields.entry(field.name().to_string()).or_default();
508            }
509            self.spans.lock().unwrap().push(CapturedSpan {
510                name: attrs.metadata().name().to_string(),
511                fields,
512            });
513        }
514
515        fn on_event(
516            &self,
517            event: &tracing::Event<'_>,
518            _ctx: tracing_subscriber::layer::Context<'_, S>,
519        ) {
520            let mut visitor = FieldVisitor(Vec::new());
521            event.record(&mut visitor);
522            let fields: HashMap<String, String> = visitor.0.into_iter().collect();
523            self.events.lock().unwrap().push(CapturedEvent {
524                level: *event.metadata().level(),
525                target: event.metadata().target().to_string(),
526                fields,
527            });
528        }
529    }
530
531    fn with_captured_tracing<F>(f: F) -> CaptureHandle
532    where
533        F: FnOnce(),
534    {
535        let (layer, handle) = SpanCapture::new();
536        let subscriber = tracing_subscriber::registry().with(layer);
537        tracing::subscriber::with_default(subscriber, f);
538        handle
539    }
540
541    // =====================================================================
542    // Command effect tests
543    // =====================================================================
544
545    #[test]
546    fn trace_command_effect_emits_span() {
547        let handle = with_captured_tracing(|| {
548            trace_command_effect("task", || 42);
549        });
550
551        let spans = handle.spans();
552        let cmd_spans: Vec<_> = spans
553            .iter()
554            .filter(|s| s.name == "effect.command")
555            .collect();
556        assert!(!cmd_spans.is_empty(), "expected effect.command span");
557        assert!(cmd_spans[0].fields.contains_key("command_type"));
558    }
559
560    #[test]
561    fn trace_command_effect_returns_value() {
562        let result = trace_command_effect("test", || 42);
563        assert_eq!(result, 42);
564    }
565
566    #[test]
567    fn trace_command_effect_debug_events() {
568        let handle = with_captured_tracing(|| {
569            trace_command_effect("file_io", || {});
570        });
571
572        let events = handle.events();
573        let start_events: Vec<_> = events
574            .iter()
575            .filter(|e| {
576                e.target == "ftui.effect"
577                    && e.fields
578                        .get("message")
579                        .is_some_and(|m| m.contains("started"))
580            })
581            .collect();
582        assert!(!start_events.is_empty(), "expected start event");
583
584        let complete_events: Vec<_> = events
585            .iter()
586            .filter(|e| {
587                e.target == "ftui.effect"
588                    && e.fields
589                        .get("message")
590                        .is_some_and(|m| m.contains("completed"))
591            })
592            .collect();
593        assert!(!complete_events.is_empty(), "expected complete event");
594
595        let evt = &complete_events[0];
596        assert!(
597            evt.fields.contains_key("duration_us"),
598            "missing duration_us"
599        );
600        assert!(
601            evt.fields.contains_key("effect_duration_us"),
602            "missing effect_duration_us histogram"
603        );
604    }
605
606    #[test]
607    fn record_command_effect_emits_span() {
608        let handle = with_captured_tracing(|| {
609            record_command_effect("clipboard", 150);
610        });
611
612        let spans = handle.spans();
613        let cmd_spans: Vec<_> = spans
614            .iter()
615            .filter(|s| s.name == "effect.command")
616            .collect();
617        assert!(!cmd_spans.is_empty());
618        assert_eq!(
619            cmd_spans[0].fields.get("command_type").unwrap(),
620            "clipboard"
621        );
622    }
623
624    // =====================================================================
625    // Subscription effect tests
626    // =====================================================================
627
628    #[test]
629    fn record_subscription_start_emits_span() {
630        let handle = with_captured_tracing(|| {
631            record_subscription_start("timer", 42);
632        });
633
634        let spans = handle.spans();
635        let sub_spans: Vec<_> = spans
636            .iter()
637            .filter(|s| s.name == "effect.subscription")
638            .collect();
639        assert!(!sub_spans.is_empty(), "expected effect.subscription span");
640        assert!(sub_spans[0].fields.contains_key("sub_type"));
641        assert!(sub_spans[0].fields.contains_key("active"));
642    }
643
644    #[test]
645    fn record_subscription_stop_emits_span() {
646        let handle = with_captured_tracing(|| {
647            record_subscription_stop("keyboard", 7, 100);
648        });
649
650        let spans = handle.spans();
651        let sub_spans: Vec<_> = spans
652            .iter()
653            .filter(|s| s.name == "effect.subscription")
654            .collect();
655        assert!(!sub_spans.is_empty());
656        assert!(sub_spans[0].fields.contains_key("event_count"));
657    }
658
659    // =====================================================================
660    // Warning/error log tests
661    // =====================================================================
662
663    #[test]
664    fn warn_effect_timeout_emits_warn_event() {
665        let handle = with_captured_tracing(|| {
666            warn_effect_timeout("task", 500_000);
667        });
668
669        let events = handle.events();
670        let warn_events: Vec<_> = events
671            .iter()
672            .filter(|e| e.level == tracing::Level::WARN && e.target == "ftui.effect")
673            .collect();
674        assert!(!warn_events.is_empty(), "expected WARN event for timeout");
675    }
676
677    #[test]
678    fn error_effect_panic_emits_error_event() {
679        let handle = with_captured_tracing(|| {
680            error_effect_panic("subscription", "thread panicked");
681        });
682
683        let events = handle.events();
684        let error_events: Vec<_> = events
685            .iter()
686            .filter(|e| e.level == tracing::Level::ERROR && e.target == "ftui.effect")
687            .collect();
688        assert!(!error_events.is_empty(), "expected ERROR event for panic");
689    }
690
691    // =====================================================================
692    // Counter tests
693    // =====================================================================
694
695    #[test]
696    fn counter_accessors_callable() {
697        let cmd = effects_command_total();
698        let sub = effects_subscription_total();
699        let total = effects_executed_total();
700        assert_eq!(total, cmd + sub);
701    }
702
703    #[test]
704    fn counters_increment_on_command() {
705        let before = effects_command_total();
706        trace_command_effect("test", || {});
707        let after = effects_command_total();
708        assert!(
709            after > before,
710            "command counter should increment: {before} → {after}"
711        );
712    }
713
714    #[test]
715    fn counters_increment_on_subscription() {
716        let before = effects_subscription_total();
717        record_subscription_start("test", 1);
718        let after = effects_subscription_total();
719        assert!(
720            after > before,
721            "subscription counter should increment: {before} → {after}"
722        );
723    }
724
725    // =========================================================================
726    // Queue telemetry tests (bd-2zd0a)
727    // =========================================================================
728
729    #[test]
730    fn queue_enqueue_increments_counter() {
731        let before = effects_queue_enqueued();
732        record_queue_enqueue(1);
733        let after = effects_queue_enqueued();
734        assert!(after > before, "enqueued counter should increment");
735    }
736
737    #[test]
738    fn queue_processed_increments_counter() {
739        let before = effects_queue_processed();
740        record_queue_processed();
741        let after = effects_queue_processed();
742        assert!(after > before, "processed counter should increment");
743    }
744
745    #[test]
746    fn queue_drop_increments_counter() {
747        let before = effects_queue_dropped();
748        record_queue_drop("test");
749        let after = effects_queue_dropped();
750        assert!(after > before, "dropped counter should increment");
751    }
752
753    #[test]
754    fn queue_high_water_ratchets_upward() {
755        let before = effects_queue_high_water();
756        let new_mark = before + 100;
757        record_queue_enqueue(new_mark);
758        assert!(
759            effects_queue_high_water() >= new_mark,
760            "high-water should ratchet to at least {new_mark}"
761        );
762        // Lower value should NOT reduce the high-water mark
763        record_queue_enqueue(1);
764        assert!(
765            effects_queue_high_water() >= new_mark,
766            "high-water should not decrease"
767        );
768    }
769
770    #[test]
771    fn queue_telemetry_snapshot_consistent() {
772        let snap = queue_telemetry();
773        // in_flight = enqueued - processed (saturating). Drops are rejected
774        // before being counted as enqueued, so they must NOT be subtracted —
775        // doing so would permanently understate the backlog after any
776        // overload episode.
777        assert_eq!(
778            snap.in_flight,
779            snap.enqueued.saturating_sub(snap.processed),
780            "in_flight should be enqueued - processed"
781        );
782    }
783
784    // =========================================================================
785    // Runtime dynamics tests (bd-4flji)
786    // =========================================================================
787
788    #[test]
789    fn dynamics_sub_start_increments() {
790        let before = subscription_starts_total();
791        record_dynamics_sub_start();
792        let after = subscription_starts_total();
793        assert!(after > before);
794    }
795
796    #[test]
797    fn dynamics_sub_stop_increments() {
798        let before = subscription_stops_total();
799        record_dynamics_sub_stop();
800        let after = subscription_stops_total();
801        assert!(after > before);
802    }
803
804    #[test]
805    fn dynamics_sub_panic_increments() {
806        let before = subscription_panics_total();
807        record_dynamics_sub_panic();
808        let after = subscription_panics_total();
809        assert!(after > before);
810    }
811
812    #[test]
813    fn dynamics_reconcile_records_count_and_duration() {
814        let before_count = reconcile_count();
815        let before_dur = reconcile_duration_us_total();
816        record_dynamics_reconcile(500);
817        assert!(reconcile_count() > before_count);
818        assert!(reconcile_duration_us_total() >= before_dur + 500);
819    }
820
821    #[test]
822    fn dynamics_shutdown_records_duration() {
823        record_dynamics_shutdown(1234, 2);
824        assert_eq!(shutdown_duration_us_last(), 1234);
825        let timeouts = shutdown_timed_out_total();
826        assert!(timeouts >= 2);
827    }
828
829    #[test]
830    fn dynamics_snapshot_consistent() {
831        let snap = runtime_dynamics();
832        assert_eq!(
833            snap.sub_active_estimate,
834            snap.sub_starts.saturating_sub(snap.sub_stops),
835            "active estimate = starts - stops"
836        );
837        if snap.reconciles > 0 {
838            assert!(
839                snap.reconcile_avg_us > 0 || reconcile_duration_us_total() == 0,
840                "avg should be > 0 when reconciles happened with non-zero duration"
841            );
842        }
843    }
844}