Add controlled fixture ACK observability

cai

2026-08-12 9eca12eae4372c79eb35cef972f1ab4756c0a5e0

 src/main.rs

@@ -63,9 +63,23 @@
const CONTROLLED_FIXTURE_ACK_TOPIC: &str = "controlled_fixture_attribute_ack";
const CONTROLLED_FIXTURE_PROTOCOL_VERSION: u64 = 1;
const CONTROLLED_FIXTURE_GENERATION: u64 = 1;
const CONTROLLED_FIXTURE_PROBE_RECHECKS: usize = 3;
const CONTROLLED_FIXTURE_PROBE_RECHECK_DELAY: Duration = Duration::from_millis(25);
const CONTROLLED_FIXTURE_PROBE_TTL: Duration = Duration::from_millis(250);

const CONTROLLED_FIXTURE_ACK_RESULTS: [&str; 4] =
    ["observed", "rejected", "timeout", "publish_failed"];
const CONTROLLED_FIXTURE_REJECT_REASONS: [&str; 10] = [
    "missing_attributes",
    "wrong_source",
    "missing_sequence",
    "wrong_sequence",
    "wrong_participant",
    "expired",
    "duplicate_or_old_sequence",
    "no_current_participant",
    "ack_publish_failed",
    "unknown",
];

#[derive(Debug, Deserialize)]
#[serde(rename_all = "camelCase")]
@@ -111,6 +125,90 @@
        .iter()
        .map(|byte| format!("{byte:02x}"))
        .collect()
}

fn controlled_fixture_ack_classification(
    decision: Result<(), &'static str>,
) -> (&'static str, Option<&'static str>, bool) {
    match decision {
        Ok(()) => ("observed", None, true),
        Err("timeout") => ("timeout", Some("expired"), false),
        Err(reason) if CONTROLLED_FIXTURE_REJECT_REASONS.contains(&reason) => {
            ("rejected", Some(reason), false)
        }
        Err(_) => ("rejected", Some("unknown"), false),
    }
}

fn record_controlled_fixture_probe_event(
    stage: &'static str,
    call_id: &str,
    trace_id: &str,
    sequence: &str,
    observed: bool,
    ack_result: Option<&'static str>,
    reject_reason: Option<&'static str>,
) {
    debug_assert!(ack_result.is_none_or(|value| CONTROLLED_FIXTURE_ACK_RESULTS.contains(&value)));
    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",
            stage,
            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 record_controlled_fixture_attribute_decision(
    decision: Result<(), &'static str>,
    call_id: &str,
    trace_id: &str,
    sequence: &str,
) -> (&'static str, Option<&'static str>, bool) {
    let classification = controlled_fixture_ack_classification(decision);
    record_controlled_fixture_probe_event(
        "attributes_classified",
        call_id,
        trace_id,
        sequence,
        classification.2,
        Some(classification.0),
        classification.1,
    );
    classification
}

fn controlled_fixture_probe(
@@ -171,6 +269,40 @@
        return Err("wrong_sequence");
    }
    Ok(())
}

async fn observe_controlled_fixture_attributes<F>(
    expires_at: Instant,
    actual_participant: &str,
    expected_participant: Option<&str>,
    requested_sequence: &str,
    mut read_attributes: F,
) -> Result<(), &'static str>
where
    F: FnMut() -> std::collections::HashMap<String, String>,
{
    loop {
        if Instant::now() > expires_at {
            return Err("timeout");
        }
        let decision = classify_controlled_fixture_attributes(
            actual_participant,
            expected_participant,
            &read_attributes(),
            requested_sequence,
        );
        if decision.is_ok() || !matches!(decision, Err("missing_attributes")) {
            return decision;
        }
        let Some(next_check) = Instant::now().checked_add(CONTROLLED_FIXTURE_PROBE_RECHECK_DELAY)
        else {
            return Err("timeout");
        };
        if next_check > expires_at {
            return Err("timeout");
        }
        sleep(CONTROLLED_FIXTURE_PROBE_RECHECK_DELAY).await;
    }
}

fn controlled_fixture_observer_gate(pending_probe: bool, probe_result: Option<bool>) -> bool {
@@ -966,6 +1098,26 @@
                        );
                    },
                );
                if let Some(sequence) = pending_sequence.as_deref() {
                    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(
                        if observer_started {
                            "audio_observer_allowed"
                        } else {
                            "audio_observer_blocked"
                        },
                        &call_id,
                        &trace_id,
                        sequence,
                        observed,
                        ack_result,
                        reject_reason,
                    );
                }
                if !observer_started {
                    warn!(
                        call_id = %call_id,
@@ -986,6 +1138,15 @@
                    serde_json::from_slice::<ControlledFixtureAttributeProbe>(&payload)
                {
                    if acknowledged_probe_sequences.contains(&probe.client_fixture_sequence) {
                        record_controlled_fixture_probe_event(
                            "data_received",
                            &call_id,
                            &trace_id,
                            &probe.client_fixture_sequence,
                            false,
                            Some("rejected"),
                            Some("duplicate_or_old_sequence"),
                        );
                        continue;
                    }
                }
@@ -996,6 +1157,17 @@
                    &sender.identity(),
                    user_participant_identity.as_deref(),
                );
                if let Some(probe) = pending_probe.as_ref() {
                    record_controlled_fixture_probe_event(
                        "data_received",
                        &call_id,
                        &trace_id,
                        &probe.sequence,
                        false,
                        None,
                        None,
                    );
                }
                process_controlled_fixture_probe(
                    &mut pending_probe,
                    &mut acknowledged_probe_sequences,
@@ -1060,39 +1232,68 @@
    let Some(probe) = pending_probe.take() else {
        return None;
    };
    if acknowledged_probe_sequences.contains(&probe.sequence) || Instant::now() > probe.expires_at {
    if acknowledged_probe_sequences.contains(&probe.sequence) {
        record_controlled_fixture_probe_event(
            "attributes_classified",
            call_id,
            trace_id,
            &probe.sequence,
            false,
            Some("rejected"),
            Some("duplicate_or_old_sequence"),
        );
        return Some(false);
    }
    if Instant::now() > probe.expires_at {
        record_controlled_fixture_probe_event(
            "attributes_classified",
            call_id,
            trace_id,
            &probe.sequence,
            false,
            Some("timeout"),
            Some("expired"),
        );
        return Some(false);
    }
    let Some(participant) = participant else {
        record_controlled_fixture_probe_event(
            "attributes_classified",
            call_id,
            trace_id,
            &probe.sequence,
            false,
            None,
            Some("no_current_participant"),
        );
        *pending_probe = Some(probe);
        return None;
    };
    if participant.identity() != probe.sender {
        record_controlled_fixture_probe_event(
            "attributes_classified",
            call_id,
            trace_id,
            &probe.sequence,
            false,
            Some("rejected"),
            Some("wrong_participant"),
        );
        return Some(false);
    }
    let mut decision = Err("timeout");
    for attempt in 0..CONTROLLED_FIXTURE_PROBE_RECHECKS {
        if Instant::now() > probe.expires_at {
            break;
        }
        let attributes = participant.attributes();
        decision = classify_controlled_fixture_attributes(
            &participant.identity().to_string(),
            expected_participant,
            &attributes,
            &probe.sequence,
        );
        if decision.is_ok() || !matches!(decision, Err("missing_attributes")) {
            break;
        }
        if attempt + 1 < CONTROLLED_FIXTURE_PROBE_RECHECKS {
            sleep(CONTROLLED_FIXTURE_PROBE_RECHECK_DELAY).await;
        }
    }
    let (result, input_source_category, reject_reason) = match decision {
        Ok(()) => ("observed", Some("controlled_fixture"), None),
        Err(reason) => ("rejected", None, Some(reason)),
    };
    let decision = observe_controlled_fixture_attributes(
        probe.expires_at,
        &participant.identity().to_string(),
        expected_participant,
        &probe.sequence,
        || 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,
@@ -1102,13 +1303,22 @@
        client_fixture_sequence: probe.sequence.clone(),
        result,
        input_source_category,
        reject_reason,
        reject_reason: protocol_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(
        "ack_publish_started",
        call_id,
        trace_id,
        &probe.sequence,
        observed,
        Some(ack_result),
        reject_reason,
    );
    let publish = local_participant.publish_data(DataPacket {
        payload,
        topic: Some(CONTROLLED_FIXTURE_ACK_TOPIC.to_string()),
@@ -1116,7 +1326,26 @@
        destination_identities: vec![probe.sender],
    });
    if publish.await.is_ok() {
        record_controlled_fixture_probe_event(
            "ack_publish_completed",
            call_id,
            trace_id,
            &probe.sequence,
            observed,
            Some(ack_result),
            reject_reason,
        );
        acknowledged_probe_sequences.insert(probe.sequence);
    } else {
        record_controlled_fixture_probe_event(
            "ack_publish_completed",
            call_id,
            trace_id,
            &probe.sequence,
            false,
            Some("publish_failed"),
            Some("ack_publish_failed"),
        );
    }
    Some(result == "observed")
}
@@ -4370,7 +4599,7 @@
        io::{Read, Write},
        net::TcpListener,
        sync::{
            Arc,
            Arc, Mutex,
            atomic::{AtomicUsize, Ordering},
            mpsc,
        },
@@ -4388,6 +4617,30 @@
            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> {
@@ -5042,6 +5295,140 @@
    }

    #[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();
        let call_id = "private-call-value";
        let trace_id = "private-trace-value";
        let sequence = "private-sequence-value";
        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",
                call_id,
                trace_id,
                sequence,
                observed,
                Some(ack_result),
                reject_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!(observer_starts, 0);
    }

    #[test]
    fn controlled_fixture_probe_observed_and_failure_enums_are_stable() {
        assert_eq!(
            controlled_fixture_ack_classification(Ok(())),
            ("observed", None, true)
        );
        assert_eq!(
            controlled_fixture_ack_classification(Err("timeout")),
            ("timeout", Some("expired"), false)
        );
        for reason in [
            "missing_attributes",
            "wrong_source",
            "missing_sequence",
            "wrong_sequence",
            "wrong_participant",
        ] {
            assert_eq!(
                controlled_fixture_ack_classification(Err(reason)),
                ("rejected", Some(reason), false)
            );
        }
        assert_eq!(
            controlled_fixture_ack_classification(Err("unclassified")),
            ("rejected", Some("unknown"), false)
        );
    }

    #[tokio::test]
    async fn production_attribute_observation_accepts_server_visibility_within_probe_ttl() {
        let expected = HashMap::from([
            (
                "inputSourceCategory".to_string(),
                "controlled_fixture".to_string(),
            ),
            (
                "clientFixtureSequence".to_string(),
                "fixture-01".to_string(),
            ),
        ]);
        let mut reads = 0;
        let result = observe_controlled_fixture_attributes(
            Instant::now() + CONTROLLED_FIXTURE_PROBE_TTL,
            "user-1",
            Some("user-1"),
            "fixture-01",
            || {
                reads += 1;
                if reads <= 3 {
                    HashMap::new()
                } else {
                    expected.clone()
                }
            },
        )
        .await;
        assert_eq!(result, Ok(()));
        assert_eq!(reads, 4);
    }

    #[tokio::test]
    async fn production_attribute_observation_rejects_wrong_sequence_without_audio_effect() {
        let attributes = HashMap::from([
            (
                "inputSourceCategory".to_string(),
                "controlled_fixture".to_string(),
            ),
            (
                "clientFixtureSequence".to_string(),
                "fixture-02".to_string(),
            ),
        ]);
        let result = observe_controlled_fixture_attributes(
            Instant::now() + CONTROLLED_FIXTURE_PROBE_TTL,
            "user-1",
            Some("user-1"),
            "fixture-01",
            || attributes.clone(),
        )
        .await;
        let mut observer_starts = 0;
        assert_eq!(result, Err("wrong_sequence"));
        assert!(!start_observer_after_controlled_fixture_probe(
            true,
            Some(result.is_ok()),
            || observer_starts += 1,
        ));
        assert_eq!(observer_starts, 0);
    }

    #[test]
    fn controlled_fixture_ack_payload_is_reliable_and_redacted() {
        let ack = ControlledFixtureAttributeAck {
            message_type: CONTROLLED_FIXTURE_ACK_TOPIC,