fix(helper): project fixture probe events to runtime logs

cai

2026-08-12 ea40c46b8b0dc548b5240df69dcf986254360038

 src/main.rs

@@ -158,43 +158,42 @@
    debug_assert!(
        reject_reason.is_none_or(|value| CONTROLLED_FIXTURE_REJECT_REASONS.contains(&value))
    );
    if let Some(ack_result) = ack_result {
        info!(
            event = "controlled_fixture_attribute_probe",
    println!(
        "{}",
        controlled_fixture_probe_event(
            stage,
            call_id_hash,
            trace_id_hash,
            generation,
            sequence,
            observed,
            ack_result,
            reject_reason = reject_reason.unwrap_or("unknown"),
            call_id_hash,
            trace_id_hash,
            generation,
            sequence_hash = %sha256_hex(sequence),
            "runtime helper controlled fixture probe state"
        );
    } else if let Some(reject_reason) = reject_reason {
        info!(
            event = "controlled_fixture_attribute_probe",
            stage,
            observed,
            reject_reason,
            call_id_hash,
            trace_id_hash,
            generation,
            sequence_hash = %sha256_hex(sequence),
            "runtime helper controlled fixture probe state"
        );
    } else {
        info!(
            event = "controlled_fixture_attribute_probe",
            stage,
            observed,
            call_id_hash,
            trace_id_hash,
            generation,
            sequence_hash = %sha256_hex(sequence),
            "runtime helper controlled fixture probe state"
        )
        );
    }

fn controlled_fixture_probe_event(
    stage: &'static str,
    call_id_hash: &str,
    trace_id_hash: &str,
    generation: u64,
    sequence: &str,
    observed: bool,
    ack_result: Option<&'static str>,
    reject_reason: Option<&'static str>,
) -> serde_json::Value {
    json!({
        "event": "controlled_fixture_attribute_probe",
        "stage": stage,
        "observed": observed,
        "ack_result": ack_result,
        "reject_reason": reject_reason,
        "call_id_hash": call_id_hash,
        "trace_id_hash": trace_id_hash,
        "generation": generation,
        "sequence_hash": sha256_hex(sequence),
    })
}

fn record_controlled_fixture_attribute_decision(
@@ -4654,7 +4653,7 @@
        io::{Read, Write},
        net::TcpListener,
        sync::{
            Arc, Mutex,
            Arc,
            atomic::{AtomicUsize, Ordering},
            mpsc,
        },
@@ -4672,30 +4671,6 @@
            participant: String,
            attributes: HashMap<String, String>,
        },
    }

    #[derive(Clone, Default)]
    struct CapturedLogs(Arc<Mutex<Vec<u8>>>);

    struct CapturedLogWriter(Arc<Mutex<Vec<u8>>>);

    impl Write for CapturedLogWriter {
        fn write(&mut self, bytes: &[u8]) -> std::io::Result<usize> {
            self.0.lock().unwrap().extend_from_slice(bytes);
            Ok(bytes.len())
        }

        fn flush(&mut self) -> std::io::Result<()> {
            Ok(())
        }
    }

    impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for CapturedLogs {
        type Writer = CapturedLogWriter;

        fn make_writer(&'a self) -> Self::Writer {
            CapturedLogWriter(self.0.clone())
        }
    }

    fn drive_pre_audio_order_test_seam(events: &[PreAudioOrderEvent]) -> Vec<&'static str> {
@@ -5353,31 +5328,51 @@
    }

    #[test]
    fn controlled_fixture_probe_failure_log_is_fixed_redacted_and_has_no_audio_effect() {
        let logs = CapturedLogs::default();
        let subscriber = tracing_subscriber::fmt()
            .without_time()
            .with_ansi(false)
            .with_writer(logs.clone())
            .finish();
    fn controlled_fixture_probe_runtime_projection_binds_request_hashes_and_audio_gate() {
        let call_id = "private-call-value";
        let trace_id = "private-trace-value";
        let sequence = "private-sequence-value";
        let call_id_hash = sha256_hex(call_id);
        let trace_id_hash = sha256_hex(trace_id);
        let mut observer_starts = 0;
        tracing::subscriber::with_default(subscriber, || {
            let decision = Err("wrong_source");
            let (ack_result, reject_reason, observed) =
                record_controlled_fixture_attribute_decision(
                    decision,
            controlled_fixture_ack_classification(Err("wrong_source"));
        let stages = [
            ("data_received", None, None),
            ("attributes_classified", Some(ack_result), reject_reason),
            ("ack_publish_started", Some(ack_result), reject_reason),
            ("ack_publish_completed", Some(ack_result), reject_reason),
            ("audio_observer_blocked", Some(ack_result), reject_reason),
        ];
        for (stage, result, reason) in stages {
            let event = controlled_fixture_probe_event(
                stage,
                    &call_id_hash,
                    &trace_id_hash,
                    CONTROLLED_FIXTURE_GENERATION,
                    sequence,
                observed,
                result,
                reason,
                );
            record_controlled_fixture_probe_event(
                "audio_observer_blocked",
            assert_eq!(event["call_id_hash"], call_id_hash);
            assert_eq!(event["trace_id_hash"], trace_id_hash);
            assert_eq!(event["stage"], stage);
            let output = event.to_string();
            assert!(!output.contains(call_id));
            assert!(!output.contains(trace_id));
            assert!(!output.contains(sequence));
        }
        assert!(!start_observer_after_controlled_fixture_probe(
            true,
            Some(observed),
            || observer_starts += 1,
        ));
        assert_eq!(observer_starts, 0);

        let (ack_result, reject_reason, observed) = controlled_fixture_ack_classification(Ok(()));
        let allowed = controlled_fixture_probe_event(
            "audio_observer_allowed",
                &call_id_hash,
                &trace_id_hash,
                CONTROLLED_FIXTURE_GENERATION,
@@ -5386,23 +5381,13 @@
                Some(ack_result),
                reject_reason,
            );
            assert!(!start_observer_after_controlled_fixture_probe(
        assert_eq!(allowed["trace_id_hash"], trace_id_hash);
        assert!(start_observer_after_controlled_fixture_probe(
                true,
                Some(observed),
                || observer_starts += 1,
            ));
        });
        let output = String::from_utf8(logs.0.lock().unwrap().clone()).unwrap();
        assert!(output.contains("ack_result=\"rejected\""));
        assert!(output.contains("reject_reason=\"wrong_source\""));
        assert!(output.contains("observed=false"));
        assert!(output.contains(&sha256_hex(call_id)));
        assert!(output.contains(&sha256_hex(trace_id)));
        assert!(output.contains(&sha256_hex(sequence)));
        assert!(!output.contains(call_id));
        assert!(!output.contains(trace_id));
        assert!(!output.contains(sequence));
        assert_eq!(observer_starts, 0);
        assert_eq!(observer_starts, 1);
    }

    #[test]