feat: bind helper stream timing markers
| | |
| | | use reqwest::Client; |
| | | use serde::{Deserialize, Serialize}; |
| | | use serde_json::json; |
| | | use sha2::{Digest, Sha256}; |
| | | use tokio::time::{sleep, sleep_until, timeout}; |
| | | use tokio::{ |
| | | sync::{mpsc, mpsc::UnboundedReceiver, watch}, |
| | |
| | | const PCM_16K_SAMPLE_RATE_HZ: u32 = 16_000; |
| | | const BOT_NUM_CHANNELS: u16 = 1; |
| | | const TRACK_NAME: &str = "bot-main-audio"; |
| | | const STREAM_TIMING_VERSION: u32 = 1; |
| | | const STREAM_TIMING_FIRST_SEGMENT: u64 = 1; |
| | | const STREAM_TIMING_FIRST_CHUNK: u64 = 1; |
| | | const STREAM_TIMING_MAX_ELAPSED_MS: u64 = 5_000; |
| | | const STREAM_TIMING_SOURCE: &str = "stream_anchor_monotonic"; |
| | | |
| | | #[tokio::main(flavor = "multi_thread")] |
| | | async fn main() -> Result<()> { |
| | |
| | | "reasonCode": reason_code, |
| | | "retryable": retryable, |
| | | "extension": extension, |
| | | }); |
| | | println!("{payload}"); |
| | | } |
| | | |
| | | fn emit_anchored_activity( |
| | | call_id: &str, |
| | | trace_id: &str, |
| | | turn_id: &str, |
| | | event_name: &str, |
| | | marker: &RuntimeTurnStreamTimingMarker, |
| | | extension: serde_json::Value, |
| | | ) { |
| | | let payload = json!({ |
| | | "type": "cv_activity", |
| | | "callId": call_id, |
| | | "traceId": trace_id, |
| | | "turnId": turn_id, |
| | | "eventName": event_name, |
| | | "eventWallTimeMs": current_time_millis(), |
| | | "serverDeltaMs": marker.server_delta_ms, |
| | | "serverDeltaSource": STREAM_TIMING_SOURCE, |
| | | "result": "ok", |
| | | "reasonCode": null, |
| | | "retryable": null, |
| | | "extension": marker.extension_with(extension), |
| | | }); |
| | | println!("{payload}"); |
| | | } |
| | |
| | | .await?; |
| | | } |
| | | } |
| | | state.close_timing(); |
| | | if !state.completed { |
| | | warn!( |
| | | call_id = %call_id, |
| | |
| | | call_id, |
| | | trace_id, |
| | | turn, |
| | | &event, |
| | | audio_chunk, |
| | | state, |
| | | turn_pipeline_started_at, |
| | |
| | | } |
| | | Some("turn_completed") => { |
| | | state.completed = true; |
| | | state.close_timing(); |
| | | info!( |
| | | call_id = %call_id, |
| | | trace_id = %trace_id, |
| | |
| | | ); |
| | | } |
| | | Some("turn_failed") => { |
| | | state.close_timing(); |
| | | let error = event.error.as_ref(); |
| | | let reason_code = error |
| | | .and_then(|value| value.reason_code.as_deref()) |
| | |
| | | } |
| | | Some("turn_cancelled") => { |
| | | state.completed = true; |
| | | state.close_timing(); |
| | | info!( |
| | | call_id = %call_id, |
| | | trace_id = %trace_id, |
| | |
| | | } |
| | | Some("activity") => { |
| | | if let Some(activity) = event.activity.as_ref() { |
| | | if activity.event_type.as_deref() == Some("tts_first_audio_chunk_ready") { |
| | | if let Some(runtime_session_nonce) = |
| | | bridge_config.runtime_session_nonce.as_deref() |
| | | { |
| | | let _ = state.arm_timing_anchor( |
| | | call_id, |
| | | trace_id, |
| | | &turn.turn_id, |
| | | runtime_session_nonce, |
| | | &event, |
| | | ); |
| | | } |
| | | } |
| | | info!( |
| | | call_id = %call_id, |
| | | trace_id = %trace_id, |
| | |
| | | call_id: &str, |
| | | trace_id: &str, |
| | | turn: &FinishedSpeechTurn, |
| | | event: &RuntimeTurnStreamEvent, |
| | | audio_chunk: &RuntimeTurnStreamAudioChunk, |
| | | state: &mut RuntimeTurnStreamState, |
| | | turn_pipeline_started_at: Instant, |
| | |
| | | return Err(anyhow!("unsupported reply_audio_chunk format {format}")); |
| | | } |
| | | match state.reply_chunk_markers.observe(audio_chunk.segment_seq) { |
| | | ReplyChunkMarker::FirstReply => emit_activity( |
| | | call_id, |
| | | trace_id, |
| | | Some(&turn.turn_id), |
| | | "helper_first_reply_audio_chunk_received", |
| | | "ok", |
| | | None, |
| | | None, |
| | | json!({ |
| | | ReplyChunkMarker::FirstReply => { |
| | | let extension = json!({ |
| | | "segmentSeq": audio_chunk.segment_seq, |
| | | "chunkSeq": audio_chunk.chunk_seq, |
| | | "format": format.as_str(), |
| | | "bytes": payload.len(), |
| | | }), |
| | | ), |
| | | }); |
| | | if let Some(marker) = |
| | | state.record_m6(call_id, trace_id, &turn.turn_id, event, audio_chunk) |
| | | { |
| | | emit_anchored_activity( |
| | | call_id, |
| | | trace_id, |
| | | &turn.turn_id, |
| | | "helper_first_reply_audio_chunk_received", |
| | | &marker, |
| | | extension, |
| | | ); |
| | | } else { |
| | | emit_activity( |
| | | call_id, |
| | | trace_id, |
| | | Some(&turn.turn_id), |
| | | "helper_first_reply_audio_chunk_received", |
| | | "ok", |
| | | None, |
| | | None, |
| | | extension, |
| | | ); |
| | | } |
| | | } |
| | | ReplyChunkMarker::SegmentFirst => emit_activity( |
| | | call_id, |
| | | trace_id, |
| | |
| | | sink.write_pcm_frame(frame).await?; |
| | | if !state.first_audio_frame_written { |
| | | state.first_audio_frame_written = true; |
| | | emit_activity( |
| | | call_id, |
| | | trace_id, |
| | | Some(&turn.turn_id), |
| | | "bot_reply_first_audio_frame_written", |
| | | "ok", |
| | | None, |
| | | None, |
| | | json!({ |
| | | "replyPlaybackMode": state.reply_playback_mode.as_str(), |
| | | "format": format.as_str(), |
| | | "chunkSeq": audio_chunk.chunk_seq, |
| | | "replyTotalAfterVadEndMs": turn_pipeline_started_at.elapsed().as_millis() as u64, |
| | | }), |
| | | ); |
| | | let extension = json!({ |
| | | "replyPlaybackMode": state.reply_playback_mode.as_str(), |
| | | "format": format.as_str(), |
| | | "chunkSeq": audio_chunk.chunk_seq, |
| | | "replyTotalAfterVadEndMs": turn_pipeline_started_at.elapsed().as_millis() as u64, |
| | | }); |
| | | if let Some(marker) = state.record_m7() { |
| | | emit_anchored_activity( |
| | | call_id, |
| | | trace_id, |
| | | &turn.turn_id, |
| | | "bot_reply_first_audio_frame_written", |
| | | &marker, |
| | | extension, |
| | | ); |
| | | } else { |
| | | emit_activity( |
| | | call_id, |
| | | trace_id, |
| | | Some(&turn.turn_id), |
| | | "bot_reply_first_audio_frame_written", |
| | | "ok", |
| | | None, |
| | | None, |
| | | extension, |
| | | ); |
| | | } |
| | | } |
| | | sleep_until(pacing_started_at + Duration::from_millis(((index + 1) as u64) * 20)).await; |
| | | } |
| | |
| | | pcm_stream_decoder: Option<audio::PcmS16leStreamDecoder>, |
| | | pcm_stream_network_chunk_count: u64, |
| | | reply_chunk_markers: ReplyChunkMarkerState, |
| | | timing: RuntimeTurnStreamTimingState, |
| | | } |
| | | |
| | | impl Default for RuntimeTurnStreamState { |
| | |
| | | pcm_stream_decoder: None, |
| | | pcm_stream_network_chunk_count: 0, |
| | | reply_chunk_markers: ReplyChunkMarkerState::default(), |
| | | timing: RuntimeTurnStreamTimingState::default(), |
| | | } |
| | | } |
| | | } |
| | | |
| | | impl RuntimeTurnStreamState { |
| | | fn arm_timing_anchor( |
| | | &mut self, |
| | | call_id: &str, |
| | | trace_id: &str, |
| | | turn_id: &str, |
| | | runtime_session_nonce: &str, |
| | | event: &RuntimeTurnStreamEvent, |
| | | ) -> bool { |
| | | if self.timing.phase != RuntimeTurnStreamTimingPhase::Empty |
| | | || event.call_id.as_deref() != Some(call_id) |
| | | || event.trace_id.as_deref() != Some(trace_id) |
| | | || event.turn_id.as_deref() != Some(turn_id) |
| | | { |
| | | return false; |
| | | } |
| | | let Some(activity) = event.activity.as_ref() else { |
| | | return false; |
| | | }; |
| | | if activity.event_type.as_deref() != Some("tts_first_audio_chunk_ready") { |
| | | return false; |
| | | } |
| | | let Some(extension) = activity.extension.as_ref() else { |
| | | return false; |
| | | }; |
| | | let Some(anchor_id) = extension.stream_anchor_id.as_deref() else { |
| | | return false; |
| | | }; |
| | | let valid_anchor_id = (16..=64).contains(&anchor_id.len()) && anchor_id.is_ascii(); |
| | | let expected_nonce_hash = runtime_session_nonce_hash(runtime_session_nonce); |
| | | if extension.stream_timing_version != Some(STREAM_TIMING_VERSION) |
| | | || !valid_anchor_id |
| | | || extension.runtime_session_nonce_hash.as_deref() != Some(expected_nonce_hash.as_str()) |
| | | || extension.segment_seq != Some(STREAM_TIMING_FIRST_SEGMENT) |
| | | || extension.stream_timing_validation.as_deref() != Some("bound") |
| | | { |
| | | return false; |
| | | } |
| | | let Some(server_delta_ms) = extension.stream_anchor_server_delta_ms else { |
| | | return false; |
| | | }; |
| | | self.timing.anchor = Some(RuntimeTurnStreamTimingAnchor { |
| | | call_id: call_id.to_string(), |
| | | trace_id: trace_id.to_string(), |
| | | turn_id: turn_id.to_string(), |
| | | anchor_id: anchor_id.to_string(), |
| | | server_delta_ms, |
| | | runtime_session_nonce_hash: expected_nonce_hash, |
| | | segment_seq: STREAM_TIMING_FIRST_SEGMENT, |
| | | received_at: Instant::now(), |
| | | }); |
| | | self.timing.phase = RuntimeTurnStreamTimingPhase::Armed; |
| | | true |
| | | } |
| | | |
| | | fn record_m6( |
| | | &mut self, |
| | | call_id: &str, |
| | | trace_id: &str, |
| | | turn_id: &str, |
| | | event: &RuntimeTurnStreamEvent, |
| | | audio_chunk: &RuntimeTurnStreamAudioChunk, |
| | | ) -> Option<RuntimeTurnStreamTimingMarker> { |
| | | if self.timing.phase != RuntimeTurnStreamTimingPhase::Armed { |
| | | return None; |
| | | } |
| | | let anchor = self.timing.anchor.as_ref()?; |
| | | if anchor.call_id != call_id |
| | | || anchor.trace_id != trace_id |
| | | || anchor.turn_id != turn_id |
| | | || event.call_id.as_deref() != Some(call_id) |
| | | || event.trace_id.as_deref() != Some(trace_id) |
| | | || event.turn_id.as_deref() != Some(turn_id) |
| | | || audio_chunk.segment_seq != Some(anchor.segment_seq) |
| | | || audio_chunk.chunk_seq != Some(STREAM_TIMING_FIRST_CHUNK) |
| | | || audio_chunk.stream_timing_version != Some(STREAM_TIMING_VERSION) |
| | | || audio_chunk.stream_anchor_id.as_deref() != Some(anchor.anchor_id.as_str()) |
| | | { |
| | | return None; |
| | | } |
| | | let Some(marker) = RuntimeTurnStreamTimingMarker::from_anchor( |
| | | anchor, |
| | | audio_chunk.chunk_seq.unwrap_or(STREAM_TIMING_FIRST_CHUNK), |
| | | ) else { |
| | | self.close_timing(); |
| | | return None; |
| | | }; |
| | | self.timing.chunk_seq = Some(marker.chunk_seq); |
| | | self.timing.phase = RuntimeTurnStreamTimingPhase::M6Recorded; |
| | | Some(marker) |
| | | } |
| | | |
| | | fn record_m7(&mut self) -> Option<RuntimeTurnStreamTimingMarker> { |
| | | if self.timing.phase != RuntimeTurnStreamTimingPhase::M6Recorded { |
| | | return None; |
| | | } |
| | | let anchor = self.timing.anchor.as_ref()?; |
| | | let Some(marker) = RuntimeTurnStreamTimingMarker::from_anchor( |
| | | anchor, |
| | | self.timing.chunk_seq.unwrap_or(STREAM_TIMING_FIRST_CHUNK), |
| | | ) else { |
| | | self.close_timing(); |
| | | return None; |
| | | }; |
| | | self.timing.phase = RuntimeTurnStreamTimingPhase::M7Recorded; |
| | | Some(marker) |
| | | } |
| | | |
| | | fn close_timing(&mut self) { |
| | | self.timing.close(); |
| | | } |
| | | } |
| | | |
| | | #[derive(Debug, Clone, Copy, PartialEq, Eq)] |
| | | enum RuntimeTurnStreamTimingPhase { |
| | | Empty, |
| | | Armed, |
| | | M6Recorded, |
| | | M7Recorded, |
| | | Closed, |
| | | } |
| | | |
| | | struct RuntimeTurnStreamTimingState { |
| | | phase: RuntimeTurnStreamTimingPhase, |
| | | anchor: Option<RuntimeTurnStreamTimingAnchor>, |
| | | chunk_seq: Option<u64>, |
| | | } |
| | | |
| | | impl Default for RuntimeTurnStreamTimingState { |
| | | fn default() -> Self { |
| | | Self { |
| | | phase: RuntimeTurnStreamTimingPhase::Empty, |
| | | anchor: None, |
| | | chunk_seq: None, |
| | | } |
| | | } |
| | | } |
| | | |
| | | impl RuntimeTurnStreamTimingState { |
| | | fn close(&mut self) { |
| | | self.anchor = None; |
| | | self.chunk_seq = None; |
| | | self.phase = RuntimeTurnStreamTimingPhase::Closed; |
| | | } |
| | | } |
| | | |
| | | impl Drop for RuntimeTurnStreamTimingState { |
| | | fn drop(&mut self) { |
| | | self.anchor = None; |
| | | self.chunk_seq = None; |
| | | } |
| | | } |
| | | |
| | | struct RuntimeTurnStreamTimingAnchor { |
| | | call_id: String, |
| | | trace_id: String, |
| | | turn_id: String, |
| | | anchor_id: String, |
| | | server_delta_ms: u64, |
| | | runtime_session_nonce_hash: String, |
| | | segment_seq: u64, |
| | | received_at: Instant, |
| | | } |
| | | |
| | | struct RuntimeTurnStreamTimingMarker { |
| | | version: u32, |
| | | anchor_id: String, |
| | | anchor_server_delta_ms: u64, |
| | | anchor_elapsed_ms: u64, |
| | | server_delta_ms: u64, |
| | | runtime_session_nonce_hash: String, |
| | | segment_seq: u64, |
| | | chunk_seq: u64, |
| | | } |
| | | |
| | | impl RuntimeTurnStreamTimingMarker { |
| | | fn from_anchor(anchor: &RuntimeTurnStreamTimingAnchor, chunk_seq: u64) -> Option<Self> { |
| | | let elapsed_ms = u64::try_from(anchor.received_at.elapsed().as_millis()).ok()?; |
| | | if elapsed_ms > STREAM_TIMING_MAX_ELAPSED_MS { |
| | | return None; |
| | | } |
| | | Some(Self { |
| | | version: STREAM_TIMING_VERSION, |
| | | anchor_id: anchor.anchor_id.clone(), |
| | | anchor_server_delta_ms: anchor.server_delta_ms, |
| | | anchor_elapsed_ms: elapsed_ms, |
| | | server_delta_ms: anchor.server_delta_ms.checked_add(elapsed_ms)?, |
| | | runtime_session_nonce_hash: anchor.runtime_session_nonce_hash.clone(), |
| | | segment_seq: anchor.segment_seq, |
| | | chunk_seq, |
| | | }) |
| | | } |
| | | |
| | | fn extension_with(&self, extra: serde_json::Value) -> serde_json::Value { |
| | | let mut extension = match extra { |
| | | serde_json::Value::Object(value) => value, |
| | | _ => serde_json::Map::new(), |
| | | }; |
| | | extension.insert("streamTimingVersion".to_string(), json!(self.version)); |
| | | extension.insert("streamAnchorId".to_string(), json!(self.anchor_id)); |
| | | extension.insert( |
| | | "streamAnchorServerDeltaMs".to_string(), |
| | | json!(self.anchor_server_delta_ms), |
| | | ); |
| | | extension.insert("anchorElapsedMs".to_string(), json!(self.anchor_elapsed_ms)); |
| | | extension.insert( |
| | | "runtimeSessionNonceHash".to_string(), |
| | | json!(self.runtime_session_nonce_hash), |
| | | ); |
| | | extension.insert("segmentSeq".to_string(), json!(self.segment_seq)); |
| | | extension.insert("chunkSeq".to_string(), json!(self.chunk_seq)); |
| | | extension.insert("streamTimingValidation".to_string(), json!("bound")); |
| | | serde_json::Value::Object(extension) |
| | | } |
| | | } |
| | | |
| | | fn runtime_session_nonce_hash(value: &str) -> String { |
| | | let digest = Sha256::digest(value.as_bytes()); |
| | | digest[..6] |
| | | .iter() |
| | | .map(|byte| format!("{byte:02x}")) |
| | | .collect() |
| | | } |
| | | |
| | | #[derive(Debug, PartialEq, Eq)] |
| | |
| | | struct RuntimeTurnStreamEvent { |
| | | #[serde(rename = "type", alias = "event")] |
| | | event_type: Option<String>, |
| | | #[serde(rename = "callId")] |
| | | call_id: Option<String>, |
| | | #[serde(rename = "traceId")] |
| | | trace_id: Option<String>, |
| | | #[serde(rename = "turnId")] |
| | | turn_id: Option<String>, |
| | | #[serde(rename = "seq")] |
| | | seq: Option<u64>, |
| | | #[serde(rename = "replyPlaybackMode")] |
| | |
| | | chunk_seq: Option<u64>, |
| | | #[serde(rename = "segmentSeq")] |
| | | segment_seq: Option<u64>, |
| | | #[serde(rename = "streamTimingVersion")] |
| | | stream_timing_version: Option<u32>, |
| | | #[serde(rename = "streamAnchorId")] |
| | | stream_anchor_id: Option<String>, |
| | | format: Option<String>, |
| | | #[serde(rename = "sampleRate")] |
| | | sample_rate: Option<u32>, |
| | |
| | | stage: Option<String>, |
| | | #[serde(rename = "reasonCode")] |
| | | reason_code: Option<String>, |
| | | extension: Option<RuntimeTurnStreamTimingExtension>, |
| | | } |
| | | |
| | | #[derive(Clone, Deserialize)] |
| | | struct RuntimeTurnStreamTimingExtension { |
| | | #[serde(rename = "streamTimingVersion")] |
| | | stream_timing_version: Option<u32>, |
| | | #[serde(rename = "streamAnchorId")] |
| | | stream_anchor_id: Option<String>, |
| | | #[serde(rename = "streamAnchorServerDeltaMs")] |
| | | stream_anchor_server_delta_ms: Option<u64>, |
| | | #[serde(rename = "runtimeSessionNonceHash")] |
| | | runtime_session_nonce_hash: Option<String>, |
| | | #[serde(rename = "segmentSeq")] |
| | | segment_seq: Option<u64>, |
| | | #[serde(rename = "streamTimingValidation")] |
| | | stream_timing_validation: Option<String>, |
| | | } |
| | | |
| | | #[derive(Deserialize)] |
| | |
| | | |
| | | #[cfg(test)] |
| | | mod tests { |
| | | use super::{ReplyChunkMarker, ReplyChunkMarkerState, RuntimeTurnStreamEvent}; |
| | | use super::{ |
| | | ReplyChunkMarker, ReplyChunkMarkerState, RuntimeTurnStreamEvent, RuntimeTurnStreamState, |
| | | RuntimeTurnStreamTimingPhase, runtime_session_nonce_hash, |
| | | }; |
| | | |
| | | #[test] |
| | | fn reply_chunk_marker_state_emits_turn_first_once_and_later_segment_first_once() { |
| | |
| | | event.audio_chunk.and_then(|chunk| chunk.segment_seq) |
| | | ); |
| | | } |
| | | |
| | | #[test] |
| | | fn runtime_turn_stream_reads_frozen_m5_and_audio_chunk_timing_contract() { |
| | | let activity: RuntimeTurnStreamEvent = serde_json::from_str( |
| | | r#"{"type":"activity","callId":"call-1","traceId":"trace-1","turnId":"turn-1","activity":{"eventType":"tts_first_audio_chunk_ready","extension":{"streamTimingVersion":1,"streamAnchorId":"0123456789abcdef","streamAnchorServerDeltaMs":1200,"runtimeSessionNonceHash":"abcdef012345","segmentSeq":1,"streamTimingValidation":"bound"}}}"#, |
| | | ) |
| | | .expect("m5 activity event"); |
| | | let audio: RuntimeTurnStreamEvent = serde_json::from_str( |
| | | r#"{"type":"reply_audio_chunk","callId":"call-1","traceId":"trace-1","turnId":"turn-1","audioChunk":{"chunkSeq":1,"segmentSeq":1,"streamTimingVersion":1,"streamAnchorId":"0123456789abcdef","format":"pcm_s16le","payloadBase64":"AA==","last":false}}"#, |
| | | ) |
| | | .expect("timed audio chunk event"); |
| | | |
| | | assert_eq!(Some("call-1"), activity.call_id.as_deref()); |
| | | assert_eq!(Some("trace-1"), activity.trace_id.as_deref()); |
| | | assert_eq!(Some("turn-1"), activity.turn_id.as_deref()); |
| | | let extension = activity.activity.unwrap().extension.unwrap(); |
| | | assert_eq!(Some(1), extension.stream_timing_version); |
| | | assert_eq!(Some(1200), extension.stream_anchor_server_delta_ms); |
| | | assert_eq!( |
| | | Some("0123456789abcdef"), |
| | | audio.audio_chunk.unwrap().stream_anchor_id.as_deref() |
| | | ); |
| | | } |
| | | |
| | | #[test] |
| | | fn runtime_turn_stream_timing_records_m6_and_m7_once_then_rejects_terminal_late_events() { |
| | | let nonce = "runtime-nonce"; |
| | | let nonce_hash = runtime_session_nonce_hash(nonce); |
| | | let activity: RuntimeTurnStreamEvent = serde_json::from_str(&format!( |
| | | r#"{{"type":"activity","callId":"call-1","traceId":"trace-1","turnId":"turn-1","activity":{{"eventType":"tts_first_audio_chunk_ready","extension":{{"streamTimingVersion":1,"streamAnchorId":"0123456789abcdef","streamAnchorServerDeltaMs":1200,"runtimeSessionNonceHash":"{nonce_hash}","segmentSeq":1,"streamTimingValidation":"bound"}}}}}}"#, |
| | | )) |
| | | .expect("m5 activity event"); |
| | | let audio: RuntimeTurnStreamEvent = serde_json::from_str( |
| | | r#"{"type":"reply_audio_chunk","callId":"call-1","traceId":"trace-1","turnId":"turn-1","audioChunk":{"chunkSeq":1,"segmentSeq":1,"streamTimingVersion":1,"streamAnchorId":"0123456789abcdef","format":"pcm_s16le","payloadBase64":"AA==","last":false}}"#, |
| | | ) |
| | | .expect("timed audio chunk event"); |
| | | let mut state = RuntimeTurnStreamState::default(); |
| | | |
| | | assert!(state.arm_timing_anchor("call-1", "trace-1", "turn-1", nonce, &activity)); |
| | | let chunk = audio.audio_chunk.as_ref().expect("audio chunk"); |
| | | assert!( |
| | | state |
| | | .record_m6("call-1", "trace-1", "turn-1", &audio, chunk) |
| | | .is_some() |
| | | ); |
| | | assert!( |
| | | state |
| | | .record_m6("call-1", "trace-1", "turn-1", &audio, chunk) |
| | | .is_none() |
| | | ); |
| | | assert!(state.record_m7().is_some()); |
| | | assert!(state.record_m7().is_none()); |
| | | |
| | | state.close_timing(); |
| | | assert_eq!(RuntimeTurnStreamTimingPhase::Closed, state.timing.phase); |
| | | assert!(state.timing.anchor.is_none()); |
| | | assert!(!state.arm_timing_anchor("call-1", "trace-1", "turn-1", nonce, &activity)); |
| | | assert!( |
| | | state |
| | | .record_m6("call-1", "trace-1", "turn-1", &audio, chunk) |
| | | .is_none() |
| | | ); |
| | | assert!(state.record_m7().is_none()); |
| | | } |
| | | } |
| | |
| | | io::{BufRead, BufReader, Read, Write}, |
| | | net::{TcpListener, TcpStream}, |
| | | process::{Child, Command, Stdio}, |
| | | sync::{Arc, Mutex}, |
| | | sync::{Arc, Mutex, mpsc}, |
| | | thread, |
| | | time::{Duration, SystemTime, UNIX_EPOCH}, |
| | | }; |
| | |
| | | const DEFAULT_BIND_ADDR: &str = "127.0.0.1:18080"; |
| | | const HTTP_READ_LIMIT_BYTES: usize = 1024 * 1024; |
| | | const DEFAULT_START_READY_TIMEOUT_MS: u64 = 10_000; |
| | | const ANCHORED_CALLBACK_MAX_ATTEMPTS: u32 = 3; |
| | | const ANCHORED_CALLBACK_RETRY_DELAY: Duration = Duration::from_millis(50); |
| | | |
| | | pub fn service_mode_enabled() -> bool { |
| | | env::args().any(|arg| arg == "service" || arg == "--service") |
| | |
| | | trace_id, |
| | | ); |
| | | } |
| | | let child = match spawn_worker(&start_req, &profile, &state.config) { |
| | | let child = match spawn_worker(&start_req, &profile, &state.config, trace_id.as_deref()) { |
| | | Ok(value) => value, |
| | | Err(spawn_error) => { |
| | | warn!( |
| | |
| | | let runtime_session_id = format!("rt_{}", start_req.call_id); |
| | | let mut child = child; |
| | | let child_stdout = child.stdout.take(); |
| | | let event_callback_url = start_req |
| | | .event_callback |
| | | .as_ref() |
| | | .and_then(|value| value.url.clone()) |
| | | .filter(|value| !value.trim().is_empty()); |
| | | let event_callback_token = Some(profile.event_callback_token.clone()); |
| | | let event_callback_sender = if event_callback_url.is_some() { |
| | | let (sender, receiver) = mpsc::channel(); |
| | | spawn_event_callback_worker(receiver); |
| | | Some(sender) |
| | | } else { |
| | | None |
| | | }; |
| | | let session = HelperSession { |
| | | call_id: start_req.call_id.clone(), |
| | | trace_id: trace_id.clone(), |
| | | runtime_session_nonce: start_req.runtime_session_nonce.clone(), |
| | | runtime_session_id, |
| | | event_callback_url: start_req |
| | | .event_callback |
| | | .as_ref() |
| | | .and_then(|value| value.url.clone()) |
| | | .filter(|value| !value.trim().is_empty()), |
| | | event_callback_token: Some(profile.event_callback_token.clone()), |
| | | event_callback_url, |
| | | event_callback_token, |
| | | event_callback_sender, |
| | | status: "STARTING".to_string(), |
| | | bot_participant_joined: false, |
| | | bot_track_ready: false, |
| | |
| | | req: &SessionStartRequest, |
| | | profile: &AuthProfile, |
| | | config: &ServiceConfig, |
| | | trace_id: Option<&str>, |
| | | ) -> Result<Child> { |
| | | let exe = env::current_exe().context("failed to resolve helper executable")?; |
| | | let mut command = Command::new(exe); |
| | |
| | | .env("CV_CALL_ID", &req.call_id) |
| | | .env( |
| | | "CV_TRACE_ID", |
| | | req.trace_id |
| | | .clone() |
| | | trace_id |
| | | .map(str::to_string) |
| | | .unwrap_or_else(|| format!("trace_{}", req.call_id)), |
| | | ) |
| | | .env("CV_RUNTIME_CALL_ID", &req.call_id) |
| | | .env( |
| | | "CV_RUNTIME_TRACE_ID", |
| | | req.trace_id |
| | | .clone() |
| | | trace_id |
| | | .map(str::to_string) |
| | | .unwrap_or_else(|| format!("trace_{}", req.call_id)), |
| | | ) |
| | | .env("CV_RUNTIME_SESSION_NONCE", &req.runtime_session_nonce) |
| | |
| | | .and_then(Value::as_str) |
| | | .unwrap_or("worker_event"); |
| | | let result = value.get("result").and_then(Value::as_str).unwrap_or("ok"); |
| | | let callback = { |
| | | let queued_callback = { |
| | | let Ok(mut sessions) = state.sessions.lock() else { |
| | | return; |
| | | }; |
| | | let Some(session) = sessions.get_mut(call_id) else { |
| | | return; |
| | | }; |
| | | let turn_id = value.get("turnId").and_then(Value::as_str); |
| | | let terminal = matches!( |
| | | event_name, |
| | | "turn_completed" | "turn_failed" | "turn_cancelled" |
| | | ); |
| | | if event_name == "turn_bridge_requested" { |
| | | session.active_turn_id = turn_id.map(str::to_string); |
| | | } |
| | | session.last_event_type = Some(event_name.to_string()); |
| | | session.last_event_at = now_millis(); |
| | | let callback = build_event_callback_dispatch(session, value); |
| | | let callback = if is_anchored_callback(value) && !anchored_callback_bound(session, value) { |
| | | warn!( |
| | | call_id = %call_id, |
| | | trace_id = ?session.trace_id, |
| | | event_name = %event_name, |
| | | "helper rejected unbound anchored callback" |
| | | ); |
| | | None |
| | | } else { |
| | | build_event_callback_dispatch(session, value) |
| | | }; |
| | | let callback_sender = session.event_callback_sender.clone(); |
| | | if result != "ok" { |
| | | session.status = "FAILED".to_string(); |
| | | session.bot_participant_joined = false; |
| | |
| | | _ => {} |
| | | } |
| | | } |
| | | callback |
| | | if terminal && turn_id == session.active_turn_id.as_deref() { |
| | | session.active_turn_id = None; |
| | | } |
| | | callback.zip(callback_sender) |
| | | }; |
| | | if let Some(callback) = callback { |
| | | dispatch_event_callback(callback); |
| | | if let Some((callback, sender)) = queued_callback { |
| | | if sender.send(callback).is_err() { |
| | | warn!( |
| | | call_id = %call_id, |
| | | event_name = %event_name, |
| | | "helper event callback queue closed" |
| | | ); |
| | | } |
| | | } |
| | | } |
| | | |
| | |
| | | }) |
| | | } |
| | | |
| | | fn dispatch_event_callback(callback: EventCallbackDispatch) { |
| | | fn spawn_event_callback_worker(receiver: mpsc::Receiver<EventCallbackDispatch>) { |
| | | thread::spawn(move || { |
| | | let event_name = callback |
| | | .payload |
| | | .get("eventName") |
| | | .and_then(Value::as_str) |
| | | .unwrap_or("worker_event") |
| | | .to_string(); |
| | | match post_event_callback(&callback) { |
| | | run_event_callback_worker(receiver, deliver_event_callback); |
| | | }); |
| | | } |
| | | |
| | | fn run_event_callback_worker<F>(receiver: mpsc::Receiver<EventCallbackDispatch>, mut deliver: F) |
| | | where |
| | | F: FnMut(EventCallbackDispatch), |
| | | { |
| | | while let Ok(callback) = receiver.recv() { |
| | | deliver(callback); |
| | | } |
| | | } |
| | | |
| | | fn deliver_event_callback(callback: EventCallbackDispatch) { |
| | | deliver_event_callback_with(callback, post_event_callback); |
| | | } |
| | | |
| | | fn deliver_event_callback_with<F>(callback: EventCallbackDispatch, mut post: F) |
| | | where |
| | | F: FnMut(&EventCallbackDispatch) -> Result<u16>, |
| | | { |
| | | let event_name = callback |
| | | .payload |
| | | .get("eventName") |
| | | .and_then(Value::as_str) |
| | | .unwrap_or("worker_event") |
| | | .to_string(); |
| | | let max_attempts = if is_anchored_callback(&callback.payload) { |
| | | ANCHORED_CALLBACK_MAX_ATTEMPTS |
| | | } else { |
| | | 1 |
| | | }; |
| | | for attempt in 1..=max_attempts { |
| | | let result = post(&callback); |
| | | let retry = |
| | | attempt < max_attempts && !matches!(&result, Ok(status) if (200..300).contains(status)); |
| | | match result { |
| | | Ok(status) if (200..300).contains(&status) => { |
| | | info!( |
| | | call_id = %callback.call_id, |
| | | trace_id = ?callback.trace_id, |
| | | event_name = %event_name, |
| | | status = status, |
| | | attempt = attempt, |
| | | "helper event callback delivered" |
| | | ); |
| | | return; |
| | | } |
| | | Ok(status) => { |
| | | warn!( |
| | |
| | | trace_id = ?callback.trace_id, |
| | | event_name = %event_name, |
| | | status = status, |
| | | attempt = attempt, |
| | | "helper event callback rejected" |
| | | ); |
| | | } |
| | |
| | | call_id = %callback.call_id, |
| | | trace_id = ?callback.trace_id, |
| | | event_name = %event_name, |
| | | attempt = attempt, |
| | | error = %error, |
| | | "helper event callback failed" |
| | | ); |
| | | } |
| | | } |
| | | }); |
| | | if retry { |
| | | thread::sleep(ANCHORED_CALLBACK_RETRY_DELAY); |
| | | } |
| | | } |
| | | } |
| | | |
| | | fn is_anchored_callback(payload: &Value) -> bool { |
| | | matches!( |
| | | payload.get("eventName").and_then(Value::as_str), |
| | | Some("helper_first_reply_audio_chunk_received" | "bot_reply_first_audio_frame_written") |
| | | ) && payload.get("serverDeltaSource").and_then(Value::as_str) == Some("stream_anchor_monotonic") |
| | | } |
| | | |
| | | fn anchored_callback_bound(session: &HelperSession, payload: &Value) -> bool { |
| | | let extension = payload.get("extension"); |
| | | let anchor_id = extension |
| | | .and_then(|value| value.get("streamAnchorId")) |
| | | .and_then(Value::as_str); |
| | | let anchor_base = extension |
| | | .and_then(|value| value.get("streamAnchorServerDeltaMs")) |
| | | .and_then(Value::as_u64); |
| | | let elapsed = extension |
| | | .and_then(|value| value.get("anchorElapsedMs")) |
| | | .and_then(Value::as_u64); |
| | | let delta = payload.get("serverDeltaMs").and_then(Value::as_u64); |
| | | let expected_delta = |
| | | anchor_base.and_then(|base| elapsed.and_then(|value| base.checked_add(value))); |
| | | let expected_nonce_hash = crate::runtime_session_nonce_hash(&session.runtime_session_nonce); |
| | | payload.get("callId").and_then(Value::as_str) == Some(session.call_id.as_str()) |
| | | && payload.get("traceId").and_then(Value::as_str) == session.trace_id.as_deref() |
| | | && payload.get("turnId").and_then(Value::as_str) == session.active_turn_id.as_deref() |
| | | && extension |
| | | .and_then(|value| value.get("streamTimingVersion")) |
| | | .and_then(Value::as_u64) |
| | | == Some(1) |
| | | && anchor_id.is_some_and(|value| (16..=64).contains(&value.len()) && value.is_ascii()) |
| | | && extension |
| | | .and_then(|value| value.get("runtimeSessionNonceHash")) |
| | | .and_then(Value::as_str) |
| | | == Some(expected_nonce_hash.as_str()) |
| | | && extension |
| | | .and_then(|value| value.get("segmentSeq")) |
| | | .and_then(Value::as_u64) |
| | | == Some(1) |
| | | && extension |
| | | .and_then(|value| value.get("streamTimingValidation")) |
| | | .and_then(Value::as_str) |
| | | == Some("bound") |
| | | && elapsed.is_some_and(|value| value <= 5_000) |
| | | && delta == expected_delta |
| | | } |
| | | |
| | | fn post_event_callback(callback: &EventCallbackDispatch) -> Result<u16> { |
| | |
| | | runtime_session_id: String, |
| | | event_callback_url: Option<String>, |
| | | event_callback_token: Option<String>, |
| | | event_callback_sender: Option<mpsc::Sender<EventCallbackDispatch>>, |
| | | status: String, |
| | | bot_participant_joined: bool, |
| | | bot_track_ready: bool, |
| | |
| | | Err(_) => default_value, |
| | | } |
| | | } |
| | | |
| | | #[cfg(test)] |
| | | mod tests { |
| | | use super::{EventCallbackDispatch, deliver_event_callback_with, run_event_callback_worker}; |
| | | use anyhow::Result; |
| | | use serde_json::{Value, json}; |
| | | use std::{cell::RefCell, rc::Rc, sync::mpsc}; |
| | | |
| | | #[test] |
| | | fn same_session_callback_retries_m7_before_terminal() { |
| | | let (sender, receiver) = mpsc::channel(); |
| | | let dispatch = |payload| EventCallbackDispatch { |
| | | url: "http://callback.test/endpoint".to_string(), |
| | | token: "test-token".to_string(), |
| | | call_id: "call-1".to_string(), |
| | | trace_id: Some("trace-1".to_string()), |
| | | runtime_session_nonce: "test-nonce".to_string(), |
| | | payload, |
| | | }; |
| | | sender |
| | | .send(dispatch(json!({ |
| | | "eventName": "bot_reply_first_audio_frame_written", |
| | | "serverDeltaSource": "stream_anchor_monotonic" |
| | | }))) |
| | | .expect("queue m7"); |
| | | sender |
| | | .send(dispatch(json!({"eventName": "turn_completed"}))) |
| | | .expect("queue terminal"); |
| | | drop(sender); |
| | | |
| | | let observed = Rc::new(RefCell::new(Vec::new())); |
| | | let observed_for_worker = observed.clone(); |
| | | run_event_callback_worker(receiver, move |callback| { |
| | | let observed_for_post = observed_for_worker.clone(); |
| | | let mut m7_attempt = 0; |
| | | deliver_event_callback_with(callback, move |dispatch| -> Result<u16> { |
| | | let event_name = dispatch |
| | | .payload |
| | | .get("eventName") |
| | | .and_then(Value::as_str) |
| | | .expect("event name") |
| | | .to_string(); |
| | | observed_for_post.borrow_mut().push(event_name.clone()); |
| | | if event_name == "bot_reply_first_audio_frame_written" && m7_attempt == 0 { |
| | | m7_attempt += 1; |
| | | Ok(500) |
| | | } else { |
| | | Ok(200) |
| | | } |
| | | }); |
| | | }); |
| | | |
| | | assert_eq!( |
| | | vec![ |
| | | "bot_reply_first_audio_frame_written", |
| | | "bot_reply_first_audio_frame_written", |
| | | "turn_completed" |
| | | ], |
| | | *observed.borrow() |
| | | ); |
| | | } |
| | | } |