pounce_observability/

lib.rs

//! Observability wiring for POUNCE (pounce#71).
//!
//! This crate owns the `tracing` subscriber install and the bridge
//! between the structured per-iteration event and the JSON solve
//! report. It is kept separate from the leaf `pounce-common` (which
//! holds the pure color palette) because the collector needs both
//! [`pounce_nlp::solve_statistics::IterRecord`] and
//! `tracing-subscriber`.
//!
//! ## Two output channels, one event
//!
//! Each Newton iteration emits a single structured event at
//! [`ITER_TARGET`] carrying `iter`, `mu`, `alpha_primal`, … The human
//! terminal never sees this event (the colored fixed-width table,
//! printed directly by `pounce-algorithm`, is its visual form, so the
//! text console layer filters `pounce::iteration` out). Machines get
//! it two ways:
//!
//! * `POUNCE_LOG_FORMAT=json` → the JSON layer prints it to stderr;
//! * the [`IterCollectorLayer`] rebuilds an `IterRecord` from its
//!   fields and appends it to the active [`IterCaptureGuard`] slot,
//!   which the application drains into the solve report.
//!
//! The collector skips events nested inside a `restoration` span, so
//! the report captures only the outer solve's iterations (including
//! `'R'`-marked outer iters) and not the restoration sub-solve's inner
//! IPM iterations — matching the pre-tracing behavior exactly.
//!
//! ## Thread-scoped capture for embedders
//!
//! Hosts that must not claim the global subscriber (libraries embedding
//! POUNCE as a solver backend) use the scoped helpers instead of
//! [`init_subscriber`]: [`with_iter_capture`] wraps one solve in a
//! closure and returns its trajectory, [`ScopedIterCapture`] is the
//! guard-shaped equivalent, and [`collector_scope`] installs just the
//! collector for drivers that manage their own [`IterCaptureGuard`]
//! (the iteration-history application path).

#![cfg_attr(test, allow(clippy::unwrap_used, clippy::expect_used))]

use std::cell::RefCell;

use pounce_common::types::{Index, Number};
use pounce_nlp::solve_statistics::IterRecord;
use tracing::field::{Field, Visit};
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::registry::LookupSpan;

/// Target of the structured per-iteration event. The text console
/// layer filters this target out (the colored table is its human
/// form); the JSON layer and [`IterCollectorLayer`] keep it.
pub const ITER_TARGET: &str = "pounce::iteration";

/// Span name whose presence in an event's ancestry marks the event as
/// belonging to the restoration sub-solve. The collector uses it to
/// exclude inner restoration iterations from the report.
pub const RESTORATION_SPAN: &str = "restoration";

// ---- Per-solve capture slot ----

thread_local! {
    /// Active capture buffer for the current solve, or `None` when no
    /// solve on this thread is recording its iteration history.
    static CAPTURE: RefCell<Option<Vec<IterRecord>>> = const { RefCell::new(None) };
}

/// Set once at subscriber install when `POUNCE_LOG_FORMAT=json`, so the
/// per-iteration event is emitted (for the JSON sink) even when no
/// in-process capture is active.
static JSON_LOGGING: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false);

/// Set when [`install`] successfully claimed the global subscriber, whose
/// layers include the collector. [`collector_scope`] then skips its
/// shadowing thread-default install, so capture composes with the
/// global console/JSON output instead of silencing it.
static GLOBAL_COLLECTOR: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false);

/// Whether the per-iteration `pounce::iteration` event has a consumer
/// right now, so the algorithm can skip emitting it (and the field
/// evaluation it entails) when nothing would observe it.
///
/// True when either an [`IterCaptureGuard`] is active on this thread
/// (the JSON report wants the trajectory) or JSON logging is installed
/// (the stderr sink wants it). In the common default run — text logs,
/// no iter-history capture — this is `false`, so the event costs
/// nothing.
pub fn iteration_event_wanted() -> bool {
    if JSON_LOGGING.load(std::sync::atomic::Ordering::Relaxed) {
        return true;
    }
    CAPTURE.with(|c| c.borrow().is_some())
}

/// RAII activation of per-iteration capture for one solve.
///
/// Construct with [`IterCaptureGuard::start`] immediately before the
/// solve and call [`IterCaptureGuard::finish`] after it to take the
/// collected records. Solves run synchronously on one thread, so a
/// thread-local slot suffices; restoration sub-solves are excluded by
/// span scoping in the collector rather than by nesting guards.
#[must_use = "call finish() to retrieve the captured iteration history"]
pub struct IterCaptureGuard {
    /// Any buffer that was active before this guard, restored on drop
    /// so sequential or accidentally-nested solves don't clobber it.
    prev: Option<Vec<IterRecord>>,
}

impl IterCaptureGuard {
    /// Begin capturing iteration records on this thread.
    pub fn start() -> Self {
        let prev = CAPTURE.with(|c| c.borrow_mut().replace(Vec::new()));
        Self { prev }
    }

    /// End capture and return the records collected since [`start`].
    ///
    /// [`start`]: IterCaptureGuard::start
    pub fn finish(mut self) -> Vec<IterRecord> {
        let prev = self.prev.take();
        let captured = CAPTURE
            .with(|c| std::mem::replace(&mut *c.borrow_mut(), prev))
            .unwrap_or_default();
        // Skip `Drop`: it would re-restore `self.prev` (now `None`) and
        // clobber the buffer we just put back for an enclosing guard.
        std::mem::forget(self);
        captured
    }
}

impl Drop for IterCaptureGuard {
    fn drop(&mut self) {
        // Restore the previous buffer if `finish` wasn't called.
        let prev = self.prev.take();
        CAPTURE.with(|c| *c.borrow_mut() = prev);
    }
}

/// Append a record to the active capture slot, if any.
fn push_record(rec: IterRecord) {
    CAPTURE.with(|c| {
        if let Some(buf) = c.borrow_mut().as_mut() {
            buf.push(rec);
        }
    });
}

/// Append copies of `records` to the active capture slot, if any.
///
/// Called by the solver driver after it drains its own iteration-history
/// capture, so an enclosing [`IterCaptureGuard`] still receives the
/// trajectory instead of finding its buffer emptied by the driver's
/// inner guard. No-op when no capture is active on this thread.
pub fn extend_active_capture(records: &[IterRecord]) {
    if records.is_empty() {
        return;
    }
    CAPTURE.with(|c| {
        if let Some(buf) = c.borrow_mut().as_mut() {
            buf.extend_from_slice(records);
        }
    });
}

// ---- Event → IterRecord visitor ----

#[derive(Default)]
struct IterVisitor {
    rec: IterRecord,
}

impl Visit for IterVisitor {
    fn record_f64(&mut self, field: &Field, value: f64) {
        let v = value as Number;
        match field.name() {
            "objective" => self.rec.objective = v,
            "inf_pr" => self.rec.inf_pr = v,
            "inf_du" => self.rec.inf_du = v,
            "mu" => self.rec.mu = v,
            "d_norm" => self.rec.d_norm = v,
            "regularization" => self.rec.regularization = v,
            "alpha_dual" => self.rec.alpha_dual = v,
            "alpha_primal" => self.rec.alpha_primal = v,
            _ => {}
        }
    }

    fn record_i64(&mut self, field: &Field, value: i64) {
        match field.name() {
            "iter" => self.rec.iter = value as Index,
            "ls_trials" => self.rec.ls_trials = value as Index,
            _ => {}
        }
    }

    fn record_u64(&mut self, field: &Field, value: u64) {
        // Match the field directly rather than routing through
        // `record_i64` (which would `value as i64`-truncate a value
        // above `i64::MAX`). `iter`/`ls_trials` never approach that, but
        // matching here keeps the cast localized to the two real fields.
        match field.name() {
            "iter" => self.rec.iter = value as Index,
            "ls_trials" => self.rec.ls_trials = value as Index,
            _ => {}
        }
    }

    fn record_str(&mut self, field: &Field, value: &str) {
        if field.name() == "alpha_char" {
            self.rec.alpha_primal_char = value.chars().next().unwrap_or(' ');
        }
    }

    fn record_debug(&mut self, _field: &Field, _value: &dyn std::fmt::Debug) {
        // The message and any Debug-formatted fields are irrelevant to
        // the numeric record.
    }
}

// ---- Collector layer ----

/// `tracing` layer that rebuilds [`IterRecord`]s from [`ITER_TARGET`]
/// events into the active [`IterCaptureGuard`] slot.
#[derive(Debug, Default, Clone)]
pub struct IterCollectorLayer;

impl<S> Layer<S> for IterCollectorLayer
where
    S: tracing::Subscriber + for<'a> LookupSpan<'a>,
{
    fn on_event(&self, event: &tracing::Event<'_>, ctx: Context<'_, S>) {
        if event.metadata().target() != ITER_TARGET {
            return;
        }
        // Skip iterations belonging to a restoration sub-solve so the
        // report keeps only the outer trajectory.
        if let Some(scope) = ctx.event_scope(event) {
            for span in scope.from_root() {
                if span.name() == RESTORATION_SPAN {
                    return;
                }
            }
        }
        let mut visitor = IterVisitor::default();
        event.record(&mut visitor);
        push_record(visitor.rec);
    }
}

/// Per-layer filter for [`IterCollectorLayer`]: admit spans (so the
/// collector's `event_scope` can see the `restoration` ancestor for
/// scoping) plus the iteration event itself.
///
/// A per-layer filter is required so the collector does not force every
/// callsite globally enabled; without admitting spans here the filtered
/// `Context` would hide span ancestry. Defined once and reused at every
/// `with_filter` site — note the `with_filter` *call* must still live in
/// each branch, because the resulting `Filtered` type carries the
/// per-branch subscriber type parameter.
fn collector_admits(m: &tracing::Metadata<'_>) -> bool {
    m.is_span() || m.target() == ITER_TARGET
}

// ---- Scoped capture helpers ----

/// Opaque RAII scope guaranteeing [`IterCollectorLayer`] is active on
/// this thread until drop.
#[must_use = "the collector uninstalls as soon as this guard drops"]
pub struct CollectorScope {
    _default: Option<tracing::subscriber::DefaultGuard>,
}

/// Ensure [`IterCollectorLayer`] is active on this thread until the
/// returned guard drops.
///
/// For the [`IterCaptureGuard`]-managed application path: with iteration
/// history enabled the solver driver runs its own capture guard around
/// the solve and drains the records into its solve statistics, so the
/// caller only needs the collector active for the solve's duration:
///
/// ```ignore
/// let _scope = pounce_observability::collector_scope();
/// app.enable_iter_history();
/// app.optimize_tnlp(problem)?;
/// let iters = app.statistics().iterations;
/// ```
///
/// When [`init_subscriber`] has claimed the global subscriber, its
/// collector already covers this thread and the scope is a no-op.
/// Otherwise a collector-only registry is installed as the thread-default
/// subscriber, which shadows the host's own subscriber (its log output
/// from this thread is dropped) for the scope's lifetime.
pub fn collector_scope() -> CollectorScope {
    use tracing_subscriber::filter::filter_fn;
    use tracing_subscriber::prelude::*;

    if GLOBAL_COLLECTOR.load(std::sync::atomic::Ordering::Relaxed) {
        return CollectorScope { _default: None };
    }
    let collector = IterCollectorLayer.with_filter(filter_fn(collector_admits));
    let subscriber = tracing_subscriber::registry().with(collector);
    CollectorScope {
        _default: Some(tracing::subscriber::set_default(subscriber)),
    }
}

/// [`IterCaptureGuard`] bundled with a [`collector_scope`] subscriber
/// install: everything needed to capture one solve's iteration history
/// on this thread, with no `tracing` wiring on the caller's side.
///
/// For solves that don't fit inside a closure; otherwise prefer
/// [`with_iter_capture`]. Combining with the driver's own
/// iteration-history capture (`enable_iter_history`) is safe.
#[must_use = "call finish() to retrieve the captured iteration history"]
pub struct ScopedIterCapture {
    capture: IterCaptureGuard,
    _scope: CollectorScope,
}

impl ScopedIterCapture {
    /// Install the collector on this thread and begin capturing.
    pub fn start() -> Self {
        let scope = collector_scope();
        let capture = IterCaptureGuard::start();
        Self {
            capture,
            _scope: scope,
        }
    }

    /// End capture, uninstall the collector, and return the records
    /// collected since [`start`].
    ///
    /// [`start`]: ScopedIterCapture::start
    pub fn finish(self) -> Vec<IterRecord> {
        let Self { capture, _scope } = self;
        let records = capture.finish();
        drop(_scope);
        records
    }
}

/// Run `f` with iteration capture active on this thread, returning its
/// result alongside the recorded trajectory.
///
/// Equivalent to wrapping `f` in a [`ScopedIterCapture`]: installs
/// [`IterCollectorLayer`] as the thread-default subscriber,
/// activates an [`IterCaptureGuard`], runs `f`, and tears both
/// down before returning.
///
/// Records exist only for solver paths that emit the [`ITER_TARGET`]
/// event. An active-set SQP solve inside `f` captures nothing.
///
/// ```ignore
/// let (solution, iters) = pounce_observability::with_iter_capture(|| nlp.solve());
/// ```
pub fn with_iter_capture<R>(f: impl FnOnce() -> R) -> (R, Vec<IterRecord>) {
    let scope = ScopedIterCapture::start();
    let result = f();
    (result, scope.finish())
}

// ---- Tiger/rust themed text formatter ----

/// Foreground style for a log level in the tiger/rust theme.
fn level_style(level: tracing::Level) -> anstyle::Style {
    use pounce_common::style::{ALPHA_HOT, TAN, TIGER_ORANGE};
    let color = match level {
        tracing::Level::ERROR => ALPHA_HOT,
        tracing::Level::WARN => TIGER_ORANGE,
        tracing::Level::INFO => TAN,
        tracing::Level::DEBUG => anstyle::RgbColor(0x9a, 0x8c, 0x70),
        tracing::Level::TRACE => anstyle::RgbColor(0x6a, 0x5d, 0x48),
    };
    anstyle::Style::new().fg_color(Some(anstyle::Color::Rgb(color)))
}

/// Compact event formatter: `LEVEL target: message field=…`, with the
/// level rendered in the tiger/rust palette when ANSI is enabled.
struct TigerFormat;

impl<S, N> tracing_subscriber::fmt::FormatEvent<S, N> for TigerFormat
where
    S: tracing::Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> tracing_subscriber::fmt::FormatFields<'a> + 'static,
{
    fn format_event(
        &self,
        ctx: &tracing_subscriber::fmt::FmtContext<'_, S, N>,
        mut writer: tracing_subscriber::fmt::format::Writer<'_>,
        event: &tracing::Event<'_>,
    ) -> std::fmt::Result {
        let meta = event.metadata();
        let level = *meta.level();
        if writer.has_ansi_escapes() {
            let style = level_style(level);
            write!(
                writer,
                "{}{:>5}{} ",
                style.render(),
                level,
                style.render_reset()
            )?;
        } else {
            write!(writer, "{level:>5} ")?;
        }
        write!(writer, "{}: ", meta.target())?;
        ctx.field_format().format_fields(writer.by_ref(), event)?;
        writeln!(writer)
    }
}

// ---- Subscriber install ----

/// Install the global tracing subscriber for a normal run. Idempotent
/// (`try_init`): safe to call from multiple frontends or repeated
/// Python imports.
///
/// Reads `RUST_LOG` (filtering, default `info`), `POUNCE_LOG_FORMAT`
/// (`text` | `json`), and `NO_COLOR`/`CLICOLOR_FORCE` (color policy).
pub fn init_subscriber() {
    install();
}

/// Install a subscriber suitable for tests: same layers as
/// [`init_subscriber`], so iteration capture works under
/// [`IterCaptureGuard`]. Idempotent.
///
/// Currently identical to [`init_subscriber`]; kept as a distinct entry
/// point so test setup can diverge (e.g. an in-memory sink) without
/// touching the production install path. Tests needing an *isolated*
/// subscriber should build their own with `with_default` instead.
pub fn init_for_tests() {
    install();
}

fn install() {
    use tracing_subscriber::EnvFilter;
    use tracing_subscriber::filter::filter_fn;
    use tracing_subscriber::prelude::*;

    // Bridge the `log` crate into `tracing` so any remaining `log::*`
    // call sites — chiefly transitive dependencies — surface through
    // our subscriber and obey `RUST_LOG`. Idempotent; the `Err` when a
    // logger is already installed is intentionally ignored.
    let _ = tracing_log::LogTracer::init();

    let want_json = std::env::var("POUNCE_LOG_FORMAT")
        .map(|v| v.eq_ignore_ascii_case("json"))
        .unwrap_or(false);
    // Record the JSON-sink decision so `iteration_event_wanted()` keeps
    // emitting the per-iteration event for the stderr stream even when
    // no in-process capture is active.
    JSON_LOGGING.store(want_json, std::sync::atomic::Ordering::Relaxed);

    // The collector only ever wants the iteration event; it must NOT be
    // subject to the console's `pounce::iteration=off` suppression, so
    // it carries its own target filter. It is constructed inside each
    // branch so its subscriber type parameter is inferred per-branch.
    let claimed = if want_json {
        let collector = IterCollectorLayer.with_filter(filter_fn(collector_admits));
        let json_layer = tracing_subscriber::fmt::layer()
            .json()
            .with_writer(std::io::stderr)
            .with_filter(env_filter());
        tracing_subscriber::registry()
            .with(json_layer)
            .with(collector)
            .try_init()
            .is_ok()
    } else {
        let collector = IterCollectorLayer.with_filter(filter_fn(collector_admits));
        let ansi = ansi_enabled();
        let text_layer = tracing_subscriber::fmt::layer()
            .event_format(TigerFormat)
            .with_ansi(ansi)
            .with_writer(std::io::stderr)
            .with_filter(console_filter());
        tracing_subscriber::registry()
            .with(text_layer)
            .with(collector)
            .try_init()
            .is_ok()
    };
    if claimed {
        GLOBAL_COLLECTOR.store(true, std::sync::atomic::Ordering::Relaxed);
    }

    /// `RUST_LOG` filter, defaulting to `info`.
    fn env_filter() -> EnvFilter {
        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))
    }

    /// Console filter: `RUST_LOG` plus suppression of the iteration
    /// target (its human form is the colored table on stdout).
    fn console_filter() -> EnvFilter {
        let base = env_filter();
        match format!("{ITER_TARGET}=off").parse() {
            Ok(directive) => base.add_directive(directive),
            Err(_) => base,
        }
    }

    /// ANSI on unless `NO_COLOR`, with `CLICOLOR_FORCE` overriding and
    /// a terminal-capability check otherwise.
    fn ansi_enabled() -> bool {
        if anstyle_query::clicolor_force() {
            return true;
        }
        if anstyle_query::no_color() {
            return false;
        }
        anstyle_query::term_supports_ansi_color()
    }
}

#[cfg(test)]
mod tests {
    use super::*;

    fn sample_record(iter: i32, alpha: f64, c: char) -> IterRecord {
        IterRecord {
            iter,
            objective: 1.0,
            inf_pr: 2.0,
            inf_du: 3.0,
            mu: 4.0,
            d_norm: 5.0,
            regularization: 6.0,
            alpha_dual: 7.0,
            alpha_primal: alpha,
            alpha_primal_char: c,
            ls_trials: 1,
        }
    }

    #[test]
    fn iteration_event_wanted_tracks_active_capture() {
        // Default (no capture on this thread, JSON sink off): nothing
        // consumes the event, so it should be suppressed.
        assert!(!iteration_event_wanted());
        let guard = IterCaptureGuard::start();
        assert!(iteration_event_wanted(), "capture active → event wanted");
        let _ = guard.finish();
        assert!(
            !iteration_event_wanted(),
            "capture ended → event suppressed"
        );
    }

    #[test]
    fn guard_captures_pushed_records() {
        let guard = IterCaptureGuard::start();
        push_record(sample_record(0, 1.0, ' '));
        push_record(sample_record(1, 0.5, 'R'));
        let got = guard.finish();
        assert_eq!(got.len(), 2);
        assert_eq!(got[1].iter, 1);
        assert_eq!(got[1].alpha_primal_char, 'R');
    }

    #[test]
    fn no_guard_means_records_are_dropped() {
        // Without an active guard, push is a no-op (no panic, no leak).
        push_record(sample_record(0, 1.0, ' '));
        let guard = IterCaptureGuard::start();
        let got = guard.finish();
        assert!(got.is_empty());
    }

    #[test]
    fn guard_restores_previous_slot_on_finish() {
        let outer = IterCaptureGuard::start();
        push_record(sample_record(0, 1.0, ' '));
        {
            let inner = IterCaptureGuard::start();
            push_record(sample_record(99, 0.1, 'R'));
            let inner_got = inner.finish();
            assert_eq!(inner_got.len(), 1);
            assert_eq!(inner_got[0].iter, 99);
        }
        // Outer slot must still hold only its own record.
        push_record(sample_record(1, 1.0, ' '));
        let outer_got = outer.finish();
        assert_eq!(outer_got.len(), 2);
        assert_eq!(outer_got[0].iter, 0);
        assert_eq!(outer_got[1].iter, 1);
    }

    #[test]
    fn collector_excludes_restoration_nested_iterations() {
        use tracing_subscriber::filter::filter_fn;
        use tracing_subscriber::prelude::*;

        fn emit(iter: i64, ch: char) {
            let s = ch.to_string();
            tracing::info!(
                target: ITER_TARGET,
                iter = iter,
                objective = 0.0,
                alpha_primal = 1.0,
                alpha_char = s.as_str(),
            );
        }

        // Same layer wiring as `install()`: the filter must admit spans
        // so the collector's `event_scope` can see the `restoration`
        // ancestor. Regression guard for the per-layer-filter bug where
        // a `target`-only filter hid span ancestry and let inner
        // restoration iterations leak into the report.
        let collector = IterCollectorLayer.with_filter(filter_fn(collector_admits));
        let subscriber = tracing_subscriber::registry().with(collector);

        let captured = tracing::subscriber::with_default(subscriber, || {
            let guard = IterCaptureGuard::start();
            emit(0, ' '); // outer -> captured
            {
                let _resto = tracing::info_span!("restoration").entered();
                let _inner_solve = tracing::info_span!("solve").entered();
                let _inner_iter = tracing::info_span!("iteration").entered();
                emit(99, 'R'); // inner restoration sub-solve -> excluded
            }
            emit(1, ' '); // outer -> captured
            guard.finish()
        });

        let iters: Vec<i32> = captured.iter().map(|r| r.iter).collect();
        assert_eq!(
            iters,
            vec![0, 1],
            "inner restoration iteration leaked: {iters:?}"
        );
    }

    #[test]
    fn log_records_bridge_into_tracing() {
        use std::sync::{Arc, Mutex};
        use tracing_subscriber::prelude::*;

        // Minimal layer that records each event's `message` field.
        #[derive(Clone)]
        struct CaptureLayer {
            buf: Arc<Mutex<Vec<String>>>,
        }
        impl<S: tracing::Subscriber> tracing_subscriber::Layer<S> for CaptureLayer {
            fn on_event(
                &self,
                event: &tracing::Event<'_>,
                _ctx: tracing_subscriber::layer::Context<'_, S>,
            ) {
                struct V<'a>(&'a mut Vec<String>);
                impl tracing::field::Visit for V<'_> {
                    fn record_debug(&mut self, f: &Field, value: &dyn std::fmt::Debug) {
                        if f.name() == "message" {
                            self.0.push(format!("{value:?}"));
                        }
                    }
                }
                let mut g = self.buf.lock().unwrap_or_else(|p| p.into_inner());
                event.record(&mut V(&mut g));
            }
        }

        let buf = Arc::new(Mutex::new(Vec::new()));
        let subscriber = tracing_subscriber::registry().with(CaptureLayer { buf: buf.clone() });

        // The same bridge `install()` sets up. Global + idempotent.
        let _ = tracing_log::LogTracer::init();
        tracing::subscriber::with_default(subscriber, || {
            // A `log` record as a transitive dependency would emit.
            log::error!(target: "some_transitive_dep", "bridged log record");
        });

        let got = buf.lock().unwrap_or_else(|p| p.into_inner());
        assert!(
            got.iter().any(|m| m.contains("bridged log record")),
            "log record did not reach the tracing layer; captured: {got:?}"
        );
    }

    /// Emit a synthetic `pounce::iteration` event as the algorithm does.
    fn emit_iter(iter: i64, ch: char) {
        let s = ch.to_string();
        tracing::info!(
            target: ITER_TARGET,
            iter = iter,
            objective = 0.5,
            alpha_primal = 1.0,
            alpha_char = s.as_str(),
        );
    }

    #[test]
    fn extend_active_capture_appends_to_enclosing_buffer() {
        let outer = IterCaptureGuard::start();
        push_record(sample_record(0, 1.0, ' '));
        let inner = IterCaptureGuard::start();
        push_record(sample_record(1, 0.5, ' '));
        let inner_got = inner.finish();
        extend_active_capture(&inner_got);
        let outer_got = outer.finish();
        let iters: Vec<i32> = outer_got.iter().map(|r| r.iter).collect();
        assert_eq!(iters, vec![0, 1]);

        extend_active_capture(&inner_got);
        let fresh = IterCaptureGuard::start();
        assert!(fresh.finish().is_empty());
    }

    #[test]
    fn with_iter_capture_captures_events_and_threads_result() {
        let (result, records) = with_iter_capture(|| {
            emit_iter(0, ' ');
            emit_iter(1, 'R');
            "sentinel"
        });
        assert_eq!(result, "sentinel");
        assert_eq!(records.len(), 2);
        assert_eq!(records[0].iter, 0);
        assert_eq!(records[1].iter, 1);
        assert_eq!(records[1].alpha_primal_char, 'R');
        assert!((records[1].objective - 0.5).abs() < 1e-12);
    }

    #[test]
    fn with_iter_capture_ignores_events_outside_scope() {
        emit_iter(7, ' '); // before the scope: no consumer
        let ((), records) = with_iter_capture(|| ());
        emit_iter(8, ' '); // after the scope: no consumer
        assert!(records.is_empty());
        assert!(
            !iteration_event_wanted(),
            "capture slot must be torn down after with_iter_capture returns"
        );
    }

    #[test]
    fn with_iter_capture_excludes_restoration_subsolve() {
        let ((), records) = with_iter_capture(|| {
            emit_iter(0, ' ');
            {
                let _resto = tracing::info_span!("restoration").entered();
                let _inner_iter = tracing::info_span!("iteration").entered();
                emit_iter(99, 'R');
            }
            emit_iter(1, ' ');
        });
        let iters: Vec<i32> = records.iter().map(|r| r.iter).collect();
        assert_eq!(
            iters,
            vec![0, 1],
            "inner restoration iteration leaked: {iters:?}"
        );
    }

    #[test]
    fn scoped_iter_capture_nesting_restores_outer_buffer() {
        let outer = ScopedIterCapture::start();
        emit_iter(0, ' ');
        let ((), inner) = with_iter_capture(|| emit_iter(99, 'R'));
        emit_iter(1, ' ');
        let outer_got = outer.finish();
        assert_eq!(inner.len(), 1);
        assert_eq!(inner[0].iter, 99);
        let iters: Vec<i32> = outer_got.iter().map(|r| r.iter).collect();
        assert_eq!(iters, vec![0, 1]);
    }

    #[test]
    fn collector_scope_feeds_manual_guard() {
        let scope = collector_scope();
        let guard = IterCaptureGuard::start();
        emit_iter(0, ' ');
        let records = guard.finish();
        drop(scope);
        assert_eq!(records.len(), 1);
        assert_eq!(records[0].iter, 0);

        let guard = IterCaptureGuard::start();
        emit_iter(1, ' ');
        assert!(guard.finish().is_empty());
    }

    #[test]
    fn with_iter_capture_is_panic_safe() {
        let unwound = std::panic::catch_unwind(|| {
            let _ = with_iter_capture(|| panic!("solve blew up"));
        });
        assert!(unwound.is_err());
        assert!(
            !iteration_event_wanted(),
            "capture slot must be restored when the closure unwinds"
        );
    }

    #[test]
    fn iter_record_default_and_assignment() {
        // This checks `IterRecord` field assignment, not the `Visit`
        // impl — constructing a real `tracing::field::Field` standalone
        // needs a callsite, so the visitor's record_* arms are covered
        // end-to-end by `collector_excludes_restoration_nested_iterations`
        // (which emits real events and asserts the rebuilt `iter`s).
        let mut v = IterVisitor::default();
        v.rec.iter = 7;
        v.rec.alpha_primal = 0.25;
        v.rec.alpha_primal_char = 'S';
        assert_eq!(v.rec.iter, 7);
        assert_eq!(v.rec.alpha_primal_char, 'S');
    }
}