fix(helper): wrap fixture probe logs as activities

cai

2026-08-12 f709c9ce06731147e010f02b11b438a0eb7b9c99

 src/main.rs

@@ -6,6 +6,7 @@
    borrow::Cow,
    collections::HashSet,
    env, fs,
    future::Future,
    path::{Path, PathBuf},
    sync::{
        Arc,
@@ -110,9 +111,12 @@
    reject_reason: Option<&'static str>,
}

#[derive(Debug)]
#[derive(Clone, Debug)]
struct PendingControlledFixtureProbe {
    sender: ParticipantIdentity,
    call_id_hash: String,
    call_trace_id_hash: String,
    generation: u64,
    sequence: String,
    expires_at: Instant,
}
@@ -141,9 +145,12 @@
}

fn record_controlled_fixture_probe_event(
    runtime_call_id: &str,
    runtime_trace_id: &str,
    stage: &'static str,
    call_id: &str,
    trace_id: &str,
    call_id_hash: &str,
    trace_id_hash: &str,
    generation: u64,
    sequence: &str,
    observed: bool,
    ack_result: Option<&'static str>,
@@ -153,62 +160,147 @@
    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(
            runtime_call_id,
            runtime_trace_id,
            stage,
            call_id_hash,
            trace_id_hash,
            generation,
            sequence,
            observed,
            ack_result,
            reject_reason = reject_reason.unwrap_or("unknown"),
            call_id_hash = %sha256_hex(call_id),
            trace_id_hash = %sha256_hex(trace_id),
            generation = CONTROLLED_FIXTURE_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 = %sha256_hex(call_id),
            trace_id_hash = %sha256_hex(trace_id),
            generation = CONTROLLED_FIXTURE_GENERATION,
            sequence_hash = %sha256_hex(sequence),
            "runtime helper controlled fixture probe state"
        );
    } else {
        info!(
            event = "controlled_fixture_attribute_probe",
            stage,
            observed,
            call_id_hash = %sha256_hex(call_id),
            trace_id_hash = %sha256_hex(trace_id),
            generation = CONTROLLED_FIXTURE_GENERATION,
            sequence_hash = %sha256_hex(sequence),
            "runtime helper controlled fixture probe state"
        );
    }
        )
    );
}

fn controlled_fixture_probe_event(
    runtime_call_id: &str,
    runtime_trace_id: &str,
    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!({
        "type": "cv_activity",
        "callId": runtime_call_id,
        "traceId": runtime_trace_id,
        "turnId": null,
        "eventName": "controlled_fixture_attribute_probe",
        "eventWallTimeMs": current_time_millis(),
        "result": "ok",
        "reasonCode": null,
        "retryable": null,
        "extension": {
            "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(
    decision: Result<(), &'static str>,
    call_id: &str,
    trace_id: &str,
    runtime_call_id: &str,
    runtime_trace_id: &str,
    call_id_hash: &str,
    trace_id_hash: &str,
    generation: u64,
    sequence: &str,
) -> (&'static str, Option<&'static str>, bool) {
    let classification = controlled_fixture_ack_classification(decision);
    record_controlled_fixture_probe_event(
        runtime_call_id,
        runtime_trace_id,
        "attributes_classified",
        call_id,
        trace_id,
        call_id_hash,
        trace_id_hash,
        generation,
        sequence,
        classification.2,
        Some(classification.0),
        classification.1,
    );
    classification
}

async fn complete_controlled_fixture_ack_publish<F, E>(
    publish: F,
    runtime_call_id: &str,
    runtime_trace_id: &str,
    observed: bool,
    ack_result: &'static str,
    reject_reason: Option<&'static str>,
    call_id_hash: &str,
    trace_id_hash: &str,
    generation: u64,
    sequence: &str,
    acknowledged_probe_sequences: &mut HashSet<String>,
) -> bool
where
    F: Future<Output = Result<(), E>>,
{
    if publish.await.is_ok() {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "ack_publish_completed",
            call_id_hash,
            trace_id_hash,
            generation,
            sequence,
            observed,
            Some(ack_result),
            reject_reason,
        );
        acknowledged_probe_sequences.insert(sequence.to_string());
        observed
    } else {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "ack_publish_completed",
            call_id_hash,
            trace_id_hash,
            generation,
            sequence,
            false,
            Some("publish_failed"),
            Some("ack_publish_failed"),
        );
        false
    }
}

fn controlled_fixture_ack_from_probe(
    probe: &PendingControlledFixtureProbe,
    observed: bool,
    reject_reason: Option<&'static str>,
) -> ControlledFixtureAttributeAck {
    ControlledFixtureAttributeAck {
        message_type: CONTROLLED_FIXTURE_ACK_TOPIC,
        protocol_version: CONTROLLED_FIXTURE_PROTOCOL_VERSION,
        call_id_hash: probe.call_id_hash.clone(),
        call_trace_id_hash: probe.call_trace_id_hash.clone(),
        generation: probe.generation,
        client_fixture_sequence: probe.sequence.clone(),
        result: if observed { "observed" } else { "rejected" },
        input_source_category: observed.then_some("controlled_fixture"),
        reject_reason,
    }
}

fn controlled_fixture_probe(
@@ -233,6 +325,9 @@
    }
    Some(PendingControlledFixtureProbe {
        sender: sender.clone(),
        call_id_hash: probe.call_id_hash,
        call_trace_id_hash: probe.call_trace_id_hash,
        generation: probe.generation,
        sequence: probe.client_fixture_sequence,
        expires_at: Instant::now() + CONTROLLED_FIXTURE_PROBE_TTL,
    })
@@ -1065,20 +1160,20 @@
                    track_source = %track_source,
                    "runtime helper user_track_subscribed"
                );
                let pending_sequence = pending_probe.as_ref().map(|probe| probe.sequence.clone());
                let pending_binding = pending_probe.clone();
                let participant_for_probe = participant.clone();
                let probe_result = process_controlled_fixture_probe(
                    &mut pending_probe,
                    &mut acknowledged_probe_sequences,
                    Some(&participant_for_probe),
                    &sink,
                    user_participant_identity.as_deref(),
                    &call_id,
                    &trace_id,
                    user_participant_identity.as_deref(),
                )
                .await;
                let observer_started = start_observer_after_controlled_fixture_probe(
                    pending_sequence.is_some(),
                    pending_binding.is_some(),
                    probe_result,
                    || {
                        spawn_user_audio_frame_observer(
@@ -1098,21 +1193,24 @@
                        );
                    },
                );
                if let Some(sequence) = pending_sequence.as_deref() {
                if let Some(probe) = pending_binding.as_ref() {
                    let (ack_result, reject_reason, observed) = match probe_result {
                        Some(true) => (Some("observed"), None, true),
                        Some(false) => (Some("rejected"), Some("unknown"), false),
                        None => (None, Some("no_current_participant"), false),
                    };
                    record_controlled_fixture_probe_event(
                        &call_id,
                        &trace_id,
                        if observer_started {
                            "audio_observer_allowed"
                        } else {
                            "audio_observer_blocked"
                        },
                        &call_id,
                        &trace_id,
                        sequence,
                        &probe.call_id_hash,
                        &probe.call_trace_id_hash,
                        probe.generation,
                        &probe.sequence,
                        observed,
                        ack_result,
                        reject_reason,
@@ -1139,9 +1237,12 @@
                {
                    if acknowledged_probe_sequences.contains(&probe.client_fixture_sequence) {
                        record_controlled_fixture_probe_event(
                            "data_received",
                            &call_id,
                            &trace_id,
                            "data_received",
                            &probe.call_id_hash,
                            &probe.call_trace_id_hash,
                            probe.generation,
                            &probe.client_fixture_sequence,
                            false,
                            Some("rejected"),
@@ -1159,9 +1260,12 @@
                );
                if let Some(probe) = pending_probe.as_ref() {
                    record_controlled_fixture_probe_event(
                        "data_received",
                        &call_id,
                        &trace_id,
                        "data_received",
                        &probe.call_id_hash,
                        &probe.call_trace_id_hash,
                        probe.generation,
                        &probe.sequence,
                        false,
                        None,
@@ -1173,9 +1277,9 @@
                    &mut acknowledged_probe_sequences,
                    current_user_participant.as_ref(),
                    &sink,
                    user_participant_identity.as_deref(),
                    &call_id,
                    &trace_id,
                    user_participant_identity.as_deref(),
                )
                .await;
            }
@@ -1225,18 +1329,21 @@
    acknowledged_probe_sequences: &mut HashSet<String>,
    participant: Option<&RemoteParticipant>,
    sink: &BotAudioOutputSink,
    call_id: &str,
    trace_id: &str,
    expected_participant: Option<&str>,
    runtime_call_id: &str,
    runtime_trace_id: &str,
) -> Option<bool> {
    let Some(probe) = pending_probe.take() else {
        return None;
    };
    if acknowledged_probe_sequences.contains(&probe.sequence) {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "attributes_classified",
            call_id,
            trace_id,
            &probe.call_id_hash,
            &probe.call_trace_id_hash,
            probe.generation,
            &probe.sequence,
            false,
            Some("rejected"),
@@ -1246,9 +1353,12 @@
    }
    if Instant::now() > probe.expires_at {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "attributes_classified",
            call_id,
            trace_id,
            &probe.call_id_hash,
            &probe.call_trace_id_hash,
            probe.generation,
            &probe.sequence,
            false,
            Some("timeout"),
@@ -1258,9 +1368,12 @@
    }
    let Some(participant) = participant else {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "attributes_classified",
            call_id,
            trace_id,
            &probe.call_id_hash,
            &probe.call_trace_id_hash,
            probe.generation,
            &probe.sequence,
            false,
            None,
@@ -1271,9 +1384,12 @@
    };
    if participant.identity() != probe.sender {
        record_controlled_fixture_probe_event(
            runtime_call_id,
            runtime_trace_id,
            "attributes_classified",
            call_id,
            trace_id,
            &probe.call_id_hash,
            &probe.call_trace_id_hash,
            probe.generation,
            &probe.sequence,
            false,
            Some("rejected"),
@@ -1289,31 +1405,28 @@
        || participant.attributes(),
    )
    .await;
    let protocol_reject_reason = decision.err();
    let (ack_result, reject_reason, observed) =
        record_controlled_fixture_attribute_decision(decision, call_id, trace_id, &probe.sequence);
    let result = if observed { "observed" } else { "rejected" };
    let input_source_category = observed.then_some("controlled_fixture");
    let ack = ControlledFixtureAttributeAck {
        message_type: CONTROLLED_FIXTURE_ACK_TOPIC,
        protocol_version: CONTROLLED_FIXTURE_PROTOCOL_VERSION,
        call_id_hash: sha256_hex(call_id),
        call_trace_id_hash: sha256_hex(trace_id),
        generation: CONTROLLED_FIXTURE_GENERATION,
        client_fixture_sequence: probe.sequence.clone(),
        result,
        input_source_category,
        reject_reason: protocol_reject_reason,
    };
    let (ack_result, reject_reason, observed) = record_controlled_fixture_attribute_decision(
        decision,
        runtime_call_id,
        runtime_trace_id,
        &probe.call_id_hash,
        &probe.call_trace_id_hash,
        probe.generation,
        &probe.sequence,
    );
    let ack = controlled_fixture_ack_from_probe(&probe, observed, reject_reason);
    let payload = match serde_json::to_vec(&ack) {
        Ok(payload) => payload,
        Err(_) => return Some(false),
    };
    let local_participant = sink.room.local_participant();
    record_controlled_fixture_probe_event(
        runtime_call_id,
        runtime_trace_id,
        "ack_publish_started",
        call_id,
        trace_id,
        &probe.call_id_hash,
        &probe.call_trace_id_hash,
        probe.generation,
        &probe.sequence,
        observed,
        Some(ack_result),
@@ -1325,29 +1438,22 @@
        reliable: true,
        destination_identities: vec![probe.sender],
    });
    if publish.await.is_ok() {
        record_controlled_fixture_probe_event(
            "ack_publish_completed",
            call_id,
            trace_id,
            &probe.sequence,
    Some(
        complete_controlled_fixture_ack_publish(
            publish,
            runtime_call_id,
            runtime_trace_id,
            observed,
            Some(ack_result),
            ack_result,
            reject_reason,
        );
        acknowledged_probe_sequences.insert(probe.sequence);
    } else {
        record_controlled_fixture_probe_event(
            "ack_publish_completed",
            call_id,
            trace_id,
            &probe.call_id_hash,
            &probe.call_trace_id_hash,
            probe.generation,
            &probe.sequence,
            false,
            Some("publish_failed"),
            Some("ack_publish_failed"),
        );
    }
    Some(result == "observed")
            acknowledged_probe_sequences,
        )
        .await,
    )
}

async fn handle_finished_turn(
@@ -4599,7 +4705,7 @@
        io::{Read, Write},
        net::TcpListener,
        sync::{
            Arc, Mutex,
            Arc,
            atomic::{AtomicUsize, Ordering},
            mpsc,
        },
@@ -4617,30 +4723,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> {
@@ -5223,6 +5305,9 @@
            controlled_fixture_probe(&payload, call_id, trace_id, &sender, Some("user-1"))
                .expect("valid probe");
        assert_eq!(pending.sequence, "fixture-01");
        assert_eq!(pending.call_id_hash, sha256_hex(call_id));
        assert_eq!(pending.call_trace_id_hash, sha256_hex(trace_id));
        assert_eq!(pending.generation, CONTROLLED_FIXTURE_GENERATION);
        assert!(
            controlled_fixture_probe(&payload, call_id, "other-trace", &sender, Some("user-1"),)
                .is_none()
@@ -5295,47 +5380,70 @@
    }

    #[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, call_id, trace_id, sequence);
            record_controlled_fixture_probe_event(
                "audio_observer_blocked",
        let (ack_result, reject_reason, observed) =
            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(
                call_id,
                trace_id,
                stage,
                &call_id_hash,
                &trace_id_hash,
                CONTROLLED_FIXTURE_GENERATION,
                sequence,
                observed,
                Some(ack_result),
                reject_reason,
                result,
                reason,
            );
            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!(event["type"], "cv_activity");
            assert_eq!(event["eventName"], "controlled_fixture_attribute_probe");
            assert_eq!(event["extension"]["call_id_hash"], call_id_hash);
            assert_eq!(event["extension"]["trace_id_hash"], trace_id_hash);
            assert_eq!(event["extension"]["stage"], stage);
            let output = event.to_string();
            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(
            call_id,
            trace_id,
            "audio_observer_allowed",
            &call_id_hash,
            &trace_id_hash,
            CONTROLLED_FIXTURE_GENERATION,
            sequence,
            observed,
            Some(ack_result),
            reject_reason,
        );
        assert_eq!(allowed["extension"]["trace_id_hash"], trace_id_hash);
        assert!(start_observer_after_controlled_fixture_probe(
            true,
            Some(observed),
            || observer_starts += 1,
        ));
        assert_eq!(observer_starts, 1);
    }

    #[test]
@@ -5366,6 +5474,114 @@
        );
    }

    #[test]
    fn production_probe_binding_drives_rejected_and_observed_ack_without_local_rehash() {
        let request_call_hash = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";
        let request_trace_hash = "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb";
        let probe = PendingControlledFixtureProbe {
            sender: ParticipantIdentity("user-1".to_string()),
            call_id_hash: request_call_hash.to_string(),
            call_trace_id_hash: request_trace_hash.to_string(),
            generation: CONTROLLED_FIXTURE_GENERATION,
            sequence: "fixture-01".to_string(),
            expires_at: Instant::now() + CONTROLLED_FIXTURE_PROBE_TTL,
        };

        let (ack_result, reject_reason, observed) =
            controlled_fixture_ack_classification(Err("wrong_sequence"));
        let rejected_ack = controlled_fixture_ack_from_probe(&probe, observed, reject_reason);
        let rejected_json = serde_json::to_value(&rejected_ack).unwrap();
        let mut rejected_observer_starts = 0;
        assert_eq!(ack_result, "rejected");
        assert_eq!(rejected_json["callIdHash"], request_call_hash);
        assert_eq!(rejected_json["callTraceIdHash"], request_trace_hash);
        assert_eq!(rejected_json["rejectReason"], "wrong_sequence");
        assert!(!start_observer_after_controlled_fixture_probe(
            true,
            Some(observed),
            || rejected_observer_starts += 1,
        ));
        assert_eq!(rejected_observer_starts, 0);

        let (ack_result, reject_reason, observed) = controlled_fixture_ack_classification(Ok(()));
        let observed_ack = controlled_fixture_ack_from_probe(&probe, observed, reject_reason);
        let observed_json = serde_json::to_value(&observed_ack).unwrap();
        let mut observed_observer_starts = 0;
        assert_eq!(ack_result, "observed");
        assert_eq!(observed_json["callIdHash"], request_call_hash);
        assert_eq!(observed_json["callTraceIdHash"], request_trace_hash);
        assert!(observed_json.get("rejectReason").is_none());
        assert!(start_observer_after_controlled_fixture_probe(
            true,
            Some(observed),
            || observed_observer_starts += 1,
        ));
        assert_eq!(observed_observer_starts, 1);
    }

    #[tokio::test]
    async fn production_ack_publish_failure_keeps_observer_session_and_audio_closed() {
        let mut acknowledged = HashSet::new();
        let probe_result = complete_controlled_fixture_ack_publish(
            async { Err::<(), ()>(()) },
            "runtime-call-publish-failure",
            "runtime-trace-publish-failure",
            true,
            "observed",
            None,
            "call-publish-failure",
            "trace-publish-failure",
            CONTROLLED_FIXTURE_GENERATION,
            "fixture-01",
            &mut acknowledged,
        )
        .await;
        let mut observer_starts = 0;
        let mut session_starts = 0;
        let mut audio_starts = 0;
        let mut speaking_starts = 0;
        assert!(!start_observer_after_controlled_fixture_probe(
            true,
            Some(probe_result),
            || {
                observer_starts += 1;
                session_starts += 1;
                audio_starts += 1;
                speaking_starts += 1;
            },
        ));
        assert!(!probe_result);
        assert!(acknowledged.is_empty());
        assert_eq!(observer_starts, 0);
        assert_eq!(session_starts, 0);
        assert_eq!(audio_starts, 0);
        assert_eq!(speaking_starts, 0);

        let observed_result = complete_controlled_fixture_ack_publish(
            async { Ok::<(), ()>(()) },
            "runtime-call-publish-success",
            "runtime-trace-publish-success",
            true,
            "observed",
            None,
            "call-publish-success",
            "trace-publish-success",
            CONTROLLED_FIXTURE_GENERATION,
            "fixture-02",
            &mut acknowledged,
        )
        .await;
        let mut successful_observer_starts = 0;
        assert!(start_observer_after_controlled_fixture_probe(
            true,
            Some(observed_result),
            || successful_observer_starts += 1,
        ));
        assert!(observed_result);
        assert!(acknowledged.contains("fixture-02"));
        assert_eq!(successful_observer_starts, 1);
    }

    #[tokio::test]
    async fn production_attribute_observation_accepts_server_visibility_within_probe_ttl() {
        let expected = HashMap::from([