feat: bind helper stream timing markers

Ariver

2026-07-12 b0a4e2ea93fafc4d65d474f3ada616a0ad5e19d5

 src/main.rs

@@ -34,6 +34,7 @@
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},
@@ -51,6 +52,11 @@
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<()> {
@@ -660,6 +666,31 @@
        "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}");
}
@@ -1420,6 +1451,7 @@
            .await?;
        }
    }
    state.close_timing();
    if !state.completed {
        warn!(
            call_id = %call_id,
@@ -1549,6 +1581,7 @@
                call_id,
                trace_id,
                turn,
                &event,
                audio_chunk,
                state,
                turn_pipeline_started_at,
@@ -1567,6 +1600,7 @@
        }
        Some("turn_completed") => {
            state.completed = true;
            state.close_timing();
            info!(
                call_id = %call_id,
                trace_id = %trace_id,
@@ -1577,6 +1611,7 @@
            );
        }
        Some("turn_failed") => {
            state.close_timing();
            let error = event.error.as_ref();
            let reason_code = error
                .and_then(|value| value.reason_code.as_deref())
@@ -1611,6 +1646,7 @@
        }
        Some("turn_cancelled") => {
            state.completed = true;
            state.close_timing();
            info!(
                call_id = %call_id,
                trace_id = %trace_id,
@@ -1643,6 +1679,19 @@
        }
        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,
@@ -1701,6 +1750,7 @@
    call_id: &str,
    trace_id: &str,
    turn: &FinishedSpeechTurn,
    event: &RuntimeTurnStreamEvent,
    audio_chunk: &RuntimeTurnStreamAudioChunk,
    state: &mut RuntimeTurnStreamState,
    turn_pipeline_started_at: Instant,
@@ -1724,21 +1774,37 @@
        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,
@@ -1875,21 +1941,33 @@
        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;
    }
@@ -2347,6 +2425,7 @@
    pcm_stream_decoder: Option<audio::PcmS16leStreamDecoder>,
    pcm_stream_network_chunk_count: u64,
    reply_chunk_markers: ReplyChunkMarkerState,
    timing: RuntimeTurnStreamTimingState,
}

impl Default for RuntimeTurnStreamState {
@@ -2363,8 +2442,233 @@
            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)]
@@ -2412,6 +2716,12 @@
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")]
@@ -2449,6 +2759,10 @@
    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>,
@@ -2465,6 +2779,23 @@
    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)]
@@ -3562,7 +3893,10 @@

#[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() {
@@ -3595,4 +3929,68 @@
            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());
    }
}