From f709c9ce06731147e010f02b11b438a0eb7b9c99 Mon Sep 17 00:00:00 2001
From: cai <cai@nbcai.cc>
Date: Wed, 12 Aug 2026 13:19:29 +0800
Subject: [PATCH] fix(helper): wrap fixture probe logs as activities
---
src/main.rs | 413 ++++++++++++++++++++++++++++++++++++++--------------------
1 files changed, 271 insertions(+), 142 deletions(-)
diff --git a/src/main.rs b/src/main.rs
index d40ca9e..dc3ee70 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -111,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,
}
@@ -142,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>,
@@ -154,56 +160,75 @@
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),
@@ -214,11 +239,14 @@
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: &str,
- trace_id: &str,
+ call_id_hash: &str,
+ trace_id_hash: &str,
+ generation: u64,
sequence: &str,
acknowledged_probe_sequences: &mut HashSet<String>,
) -> bool
@@ -227,9 +255,12 @@
{
if publish.await.is_ok() {
record_controlled_fixture_probe_event(
+ runtime_call_id,
+ runtime_trace_id,
"ack_publish_completed",
- call_id,
- trace_id,
+ call_id_hash,
+ trace_id_hash,
+ generation,
sequence,
observed,
Some(ack_result),
@@ -239,15 +270,36 @@
observed
} else {
record_controlled_fixture_probe_event(
+ runtime_call_id,
+ runtime_trace_id,
"ack_publish_completed",
- call_id,
- trace_id,
+ 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,
}
}
@@ -273,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,
})
@@ -1105,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(
@@ -1138,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,
@@ -1179,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"),
@@ -1199,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,
@@ -1213,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;
}
@@ -1265,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"),
@@ -1286,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"),
@@ -1298,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,
@@ -1311,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"),
@@ -1329,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),
@@ -1368,11 +1441,14 @@
Some(
complete_controlled_fixture_ack_publish(
publish,
+ runtime_call_id,
+ runtime_trace_id,
observed,
ack_result,
reject_reason,
- call_id,
- trace_id,
+ &probe.call_id_hash,
+ &probe.call_trace_id_hash,
+ probe.generation,
&probe.sequence,
acknowledged_probe_sequences,
)
@@ -4629,7 +4705,7 @@
io::{Read, Write},
net::TcpListener,
sync::{
- Arc, Mutex,
+ Arc,
atomic::{AtomicUsize, Ordering},
mpsc,
},
@@ -4647,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> {
@@ -5253,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()
@@ -5325,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]
@@ -5396,16 +5474,64 @@
);
}
+ #[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,
)
@@ -5433,11 +5559,14 @@
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,
)
--
Gitblit v1.9.3