Fix realtime feedback event correlation (#534)

This commit is contained in:
Abhishek 2026-07-14 19:49:58 +05:30 committed by GitHub
parent 5da57b3fa5
commit e08660c1fa
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
9 changed files with 497 additions and 266 deletions

View file

@ -14,6 +14,7 @@ from api.services.pipecat.in_memory_buffers import (
)
from api.services.pipecat.pipeline_metrics_aggregator import PipelineMetricsAggregator
from api.services.pipecat.tracing_config import get_trace_url
from api.services.pipecat.transcript_log_coordinator import TranscriptLogCoordinator
from api.services.posthog_client import capture_event
from api.services.workflow.pipecat_engine import PipecatEngine
from api.services.workflow_run_artifacts import upload_workflow_run_artifacts
@ -65,6 +66,7 @@ def register_event_handlers(
engine: PipecatEngine,
audio_buffer: AudioBufferProcessor,
in_memory_logs_buffer: InMemoryLogsBuffer,
transcript_log_coordinator: TranscriptLogCoordinator,
pipeline_metrics_aggregator: PipelineMetricsAggregator,
audio_config=AudioConfig,
pre_call_fetch_task: asyncio.Task | None = None,
@ -223,7 +225,12 @@ def register_event_handlers(
task: PipelineWorker,
_frame: Frame,
):
logger.debug(f"In on_pipeline_finished callback handler")
logger.debug("In on_pipeline_finished callback handler")
# Turn and feedback observers run on independent queues. Drain them
# before finalizing immutable transcripts and taking the DB snapshot.
await task.wait_for_observers()
await transcript_log_coordinator.flush()
workflow_run = await db_client.get_workflow_run_by_id(workflow_run_id)

View file

@ -1,6 +1,7 @@
import asyncio
import io
import wave
from copy import deepcopy
from datetime import UTC, datetime
from typing import List, Optional
@ -104,15 +105,9 @@ class InMemoryLogsBuffer:
def __init__(self, workflow_run_id: int):
self._workflow_run_id = workflow_run_id
self._events: List[dict] = []
self._turn_counter = 0
self._current_turn: Optional[int] = None
self._current_node_id: Optional[str] = None
self._current_node_name: Optional[str] = None
self._user_speech_start_timestamp: Optional[str] = None
self._user_speech_end_timestamp: Optional[str] = None
self._user_speech_start_from_vad = False
self._user_speech_end_from_vad = False
self._bot_speech_start_timestamp: Optional[str] = None
self._bot_speech_end_timestamp: Optional[str] = None
def set_current_node(self, node_id: str, node_name: str):
"""Set the current node ID and name to be injected into subsequent events."""
@ -129,153 +124,44 @@ class InMemoryLogsBuffer:
"""Get the current node name."""
return self._current_node_name
@staticmethod
def _now_iso() -> str:
return datetime.now(UTC).isoformat(timespec="milliseconds")
def set_current_turn(self, turn: int) -> None:
"""Set the fallback turn for non-transcript events."""
self._current_turn = turn
def mark_user_started_speaking(
self, timestamp: Optional[str] = None, *, from_vad: bool = False
async def append(
self,
event: dict,
*,
timestamp: Optional[str] = None,
turn: Optional[int] = None,
node_id: Optional[str] = None,
node_name: Optional[str] = None,
use_current_node: bool = True,
):
"""Record when the user started speaking for the current turn."""
vad_interval_is_open = (
self._user_speech_start_from_vad and self._user_speech_end_timestamp is None
)
if vad_interval_is_open and not from_vad:
return
self._user_speech_start_timestamp = timestamp or self._now_iso()
self._user_speech_end_timestamp = None
self._user_speech_start_from_vad = from_vad
self._user_speech_end_from_vad = False
self._update_latest_payload_start_timestamp(
RealtimeFeedbackType.USER_TRANSCRIPTION.value,
self._user_speech_start_timestamp,
require_final=True,
)
def mark_user_stopped_speaking(
self, timestamp: Optional[str] = None, *, from_vad: bool = False
):
"""Record when the user stopped speaking and update the latest user event."""
if self._user_speech_end_from_vad and not from_vad:
return
self._user_speech_end_timestamp = timestamp or self._now_iso()
self._user_speech_end_from_vad = from_vad
self._update_latest_payload_end_timestamp(
RealtimeFeedbackType.USER_TRANSCRIPTION.value,
self._user_speech_end_timestamp,
require_final=True,
)
def mark_bot_started_speaking(self, timestamp: Optional[str] = None):
"""Record when the bot started speaking for the current assistant turn."""
self._bot_speech_start_timestamp = timestamp or self._now_iso()
self._bot_speech_end_timestamp = None
self._update_latest_payload_start_timestamp(
RealtimeFeedbackType.BOT_TEXT.value,
self._bot_speech_start_timestamp,
)
def mark_bot_stopped_speaking(self, timestamp: Optional[str] = None):
"""Record when the bot stopped speaking and update the latest bot event."""
self._bot_speech_end_timestamp = timestamp or self._now_iso()
self._update_latest_payload_end_timestamp(
RealtimeFeedbackType.BOT_TEXT.value,
self._bot_speech_end_timestamp,
)
def _find_latest_open_payload(
self, event_type: str, *, require_final: bool = False
) -> dict | None:
for event in reversed(self._events):
if event.get("type") != event_type:
continue
payload = event.get("payload")
if not isinstance(payload, dict):
continue
if require_final and payload.get("final") is not True:
continue
if payload.get("end_timestamp"):
continue
return payload
return None
def _update_latest_payload_start_timestamp(
self, event_type: str, start_timestamp: str, *, require_final: bool = False
):
payload = self._find_latest_open_payload(
event_type, require_final=require_final
)
if payload is not None:
payload["timestamp"] = start_timestamp
def _update_latest_payload_end_timestamp(
self, event_type: str, end_timestamp: str, *, require_final: bool = False
):
payload = self._find_latest_open_payload(
event_type, require_final=require_final
)
if payload is not None:
payload["end_timestamp"] = end_timestamp
def _event_with_speech_timestamps(self, event: dict) -> dict:
event_type = event.get("type")
payload = event.get("payload")
if not isinstance(payload, dict):
return event
payload_with_timestamps = dict(payload)
if (
event_type == RealtimeFeedbackType.USER_TRANSCRIPTION.value
and payload.get("final") is True
):
if self._user_speech_start_timestamp:
payload_with_timestamps["timestamp"] = self._user_speech_start_timestamp
if self._user_speech_end_timestamp:
payload_with_timestamps["end_timestamp"] = (
self._user_speech_end_timestamp
)
elif event_type == RealtimeFeedbackType.BOT_TEXT.value:
bot_interval_is_active = self._bot_speech_end_timestamp is None
if bot_interval_is_active and self._bot_speech_start_timestamp:
payload_with_timestamps["timestamp"] = self._bot_speech_start_timestamp
if payload_with_timestamps == payload:
return event
return {**event, "payload": payload_with_timestamps}
async def append(self, event: dict):
"""Append a feedback event to the buffer with timestamp and current node."""
event = self._event_with_speech_timestamps(event)
"""Append an immutable event with optional correlation metadata."""
if use_current_node:
node_id = self._current_node_id if node_id is None else node_id
node_name = self._current_node_name if node_name is None else node_name
timestamped_event = stamp_realtime_feedback_event(
event,
timestamp=self._now_iso(),
turn=self._turn_counter,
node_id=self._current_node_id,
node_name=self._current_node_name,
deepcopy(event),
timestamp=timestamp or datetime.now(UTC).isoformat(timespec="milliseconds"),
turn=self._current_turn if turn is None else turn,
node_id=node_id,
node_name=node_name,
)
self._events.append(timestamped_event)
logger.trace(
f"Appended event {event.get('type')} to logs buffer for workflow {self._workflow_run_id}"
)
def increment_turn(self):
"""Increment turn counter (called on user transcription completion)."""
self._turn_counter += 1
logger.trace(
f"Incremented turn counter to {self._turn_counter} for workflow {self._workflow_run_id}"
)
def _sorted_events(self) -> List[dict]:
# Stable sort by the realtime (payload) timestamp when available, falling
# back to the buffer-append timestamp. Python's sort is stable, so events
# sharing a key retain their original insertion order — this keeps
# consecutive bot-text chunks of a single turn contiguous.
# Stable sort by the top-level event timestamp used by the persisted
# realtime feedback schema. Legacy events without one fall back to their
# payload timestamp. Events sharing a key retain insertion order.
return sorted(self._events, key=realtime_feedback_event_sort_key)
def get_events(self) -> List[dict]:
"""Get all events for final storage, ordered by realtime timestamp."""
"""Get all events for final storage, ordered by event timestamp."""
return self._sorted_events()
def contains_user_speech(self) -> bool:

View file

@ -166,4 +166,4 @@ def stamp_realtime_feedback_event(
def realtime_feedback_event_sort_key(event: dict[str, Any]) -> str:
payload_timestamp = (event.get("payload") or {}).get("timestamp")
return payload_timestamp or event.get("timestamp") or ""
return event.get("timestamp") or payload_timestamp or ""

View file

@ -21,7 +21,6 @@ node changes.
"""
import json
from datetime import UTC, datetime
from typing import TYPE_CHECKING, Awaitable, Callable, Optional, Set
from loguru import logger
@ -37,6 +36,9 @@ from api.services.pipecat.realtime_feedback_events import (
if TYPE_CHECKING:
from api.services.pipecat.in_memory_buffers import InMemoryLogsBuffer
from api.services.pipecat.transcript_log_coordinator import (
TranscriptLogCoordinator,
)
from pipecat.frames.frames import (
BotStartedSpeakingFrame,
@ -55,10 +57,6 @@ from pipecat.frames.frames import (
TTSTextFrame,
UserMuteStartedFrame,
UserMuteStoppedFrame,
UserStartedSpeakingFrame,
UserStoppedSpeakingFrame,
VADUserStartedSpeakingFrame,
VADUserStoppedSpeakingFrame,
)
from pipecat.metrics.metrics import TTFBMetricsData
from pipecat.observers.base_observer import BaseObserver, FramePushed
@ -67,10 +65,6 @@ from pipecat.transports.base_output import BaseOutputTransport
from pipecat.utils.enums import RealtimeFeedbackType
def _epoch_seconds_to_utc_iso(timestamp: float) -> str:
return datetime.fromtimestamp(timestamp, UTC).isoformat(timespec="milliseconds")
class RealtimeFeedbackObserver(BaseObserver):
"""Observer that sends real-time events via WebSocket and persists final transcripts.
@ -147,35 +141,13 @@ class RealtimeFeedbackObserver(BaseObserver):
return
# Bot speaking state - WS only (ephemeral state signals, not persisted)
elif isinstance(frame, BotStartedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_bot_started_speaking()
await self._send_ws(
{"type": RealtimeFeedbackType.BOT_STARTED_SPEAKING.value, "payload": {}}
)
elif isinstance(frame, BotStoppedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_bot_stopped_speaking()
await self._send_ws(
{"type": RealtimeFeedbackType.BOT_STOPPED_SPEAKING.value, "payload": {}}
)
elif isinstance(frame, UserStartedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_user_started_speaking()
elif isinstance(frame, UserStoppedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_user_stopped_speaking()
elif isinstance(frame, VADUserStartedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_user_started_speaking(
_epoch_seconds_to_utc_iso(frame.timestamp - frame.start_secs),
from_vad=True,
)
elif isinstance(frame, VADUserStoppedSpeakingFrame):
if self._logs_buffer:
self._logs_buffer.mark_user_stopped_speaking(
_epoch_seconds_to_utc_iso(frame.timestamp - frame.stop_secs),
from_vad=True,
)
# User mute state - WS only (ephemeral state signals, not persisted)
elif isinstance(frame, UserMuteStartedFrame):
await self._send_ws(
@ -325,42 +297,36 @@ class RealtimeFeedbackObserver(BaseObserver):
def register_turn_log_handlers(
logs_buffer: "InMemoryLogsBuffer",
transcript_coordinator: "TranscriptLogCoordinator",
user_aggregator,
assistant_aggregator,
):
"""Register event handlers on aggregators to persist final turn transcripts.
Hooks into on_user_turn_message_added and on_assistant_turn_stopped to store
complete turn text in the logs buffer. Works for both WebRTC and telephony
calls independent of WebSocket availability.
complete turn text through the turn-aware coordinator. Works for both
WebRTC and telephony calls independent of WebSocket availability.
"""
@user_aggregator.event_handler("on_user_turn_message_added")
async def on_user_turn_message_added(aggregator, message):
logs_buffer.increment_turn()
try:
await logs_buffer.append(
build_user_transcription_event(
text=message.content,
final=True,
timestamp=message.timestamp,
end_timestamp=getattr(message, "end_timestamp", None),
)
await transcript_coordinator.record_user_transcript(
text=message.content,
timestamp=message.timestamp,
end_timestamp=getattr(message, "end_timestamp", None),
)
except Exception as e:
logger.error(f"Failed to append user turn to logs buffer: {e}")
logger.error(f"Failed to coordinate user turn transcript: {e}")
@assistant_aggregator.event_handler("on_assistant_turn_stopped")
async def on_assistant_turn_stopped(aggregator, message):
if message.content:
try:
await logs_buffer.append(
build_bot_text_event(
text=message.content,
timestamp=message.timestamp,
end_timestamp=getattr(message, "end_timestamp", None),
)
await transcript_coordinator.record_assistant_transcript(
text=message.content,
timestamp=message.timestamp,
end_timestamp=getattr(message, "end_timestamp", None),
)
except Exception as e:
logger.error(f"Failed to append assistant turn to logs buffer: {e}")
logger.error(f"Failed to coordinate assistant turn transcript: {e}")

View file

@ -66,6 +66,7 @@ from api.services.pipecat.service_factory import (
from api.services.pipecat.tracing_config import (
ensure_tracing,
)
from api.services.pipecat.transcript_log_coordinator import TranscriptLogCoordinator
from api.services.pipecat.transport_setup import create_webrtc_transport
from api.services.pipecat.worker_runner import run_pipeline_worker
from api.services.pipecat.ws_sender_registry import get_ws_sender
@ -1033,6 +1034,12 @@ async def _run_pipeline_impl(
# Create pipeline task with audio configuration
task = create_pipeline_task(pipeline, workflow_run_id, audio_config)
transcript_log_coordinator = TranscriptLogCoordinator(in_memory_logs_buffer)
if task.turn_tracking_observer is None:
raise RuntimeError("Transcript logging requires turn tracking to be enabled")
transcript_log_coordinator.attach_turn_tracking_observer(
task.turn_tracking_observer
)
for runtime_session in integration_runtime_sessions:
runtime_session.attach(task)
@ -1087,7 +1094,9 @@ async def _run_pipeline_impl(
# Register turn log handlers for all call types (WebRTC and telephony)
register_turn_log_handlers(
in_memory_logs_buffer, user_context_aggregator, assistant_context_aggregator
transcript_log_coordinator,
user_context_aggregator,
assistant_context_aggregator,
)
# Register event handlers — resolve provider_id for PostHog tracking
@ -1101,6 +1110,7 @@ async def _run_pipeline_impl(
engine=engine,
audio_buffer=audio_buffer,
in_memory_logs_buffer=in_memory_logs_buffer,
transcript_log_coordinator=transcript_log_coordinator,
pipeline_metrics_aggregator=pipeline_metrics_aggregator,
audio_config=audio_config,
pre_call_fetch_task=pre_call_fetch_task,

View file

@ -0,0 +1,298 @@
"""Turn-aware coordination for immutable persisted transcript events.
The transcript text, speech timing, and logical turn lifecycle are produced by
different parts of the pipeline and can arrive in either order. This module is
the single place where those facts are joined. It emits a transcript event only
after the owning logical turn has ended (or during a final flush), and never
mutates an event after it has been appended to the logs buffer.
"""
import asyncio
from dataclasses import dataclass, field
from datetime import UTC, datetime
from typing import TYPE_CHECKING
from api.services.pipecat.realtime_feedback_events import (
build_bot_text_event,
build_user_transcription_event,
)
if TYPE_CHECKING:
from api.services.pipecat.in_memory_buffers import InMemoryLogsBuffer
from pipecat.observers.turn_tracking_observer import TurnTrackingObserver
def _now_iso() -> str:
return datetime.now(UTC).isoformat(timespec="milliseconds")
@dataclass
class _TranscriptSide:
text: str | None = None
transcript_timestamp: str | None = None
event_timestamp: str | None = None
speech_start_timestamp: str | None = None
speech_end_timestamp: str | None = None
speaking: bool = False
emitted: bool = False
node_id: str | None = None
node_name: str | None = None
@dataclass
class _TurnTranscriptState:
turn_id: int
ended: bool = False
interrupted: bool = False
user: _TranscriptSide = field(default_factory=_TranscriptSide)
assistant: _TranscriptSide = field(default_factory=_TranscriptSide)
class TranscriptLogCoordinator:
"""Join turn, transcript, and speech facts before appending log events."""
def __init__(self, logs_buffer: "InMemoryLogsBuffer"):
self._logs_buffer = logs_buffer
self._states: dict[int, _TurnTranscriptState] = {}
self._active_turn_id: int | None = None
self._lock = asyncio.Lock()
def attach_turn_tracking_observer(self, observer: "TurnTrackingObserver") -> None:
"""Subscribe to the canonical turn owner's correlated lifecycle events."""
@observer.event_handler("on_turn_started")
async def on_turn_started(_observer, turn_number: int):
await self.record_turn_started(turn_number)
@observer.event_handler("on_turn_ended")
async def on_turn_ended(
_observer,
turn_number: int,
_duration: float,
was_interrupted: bool,
):
await self.record_turn_ended(turn_number, interrupted=was_interrupted)
@observer.event_handler("on_user_speech_started_for_turn")
async def on_user_speech_started_for_turn(_observer, turn_number: int, _data):
callback_timestamp = _now_iso()
await self.record_user_started_speaking(turn_number, callback_timestamp)
@observer.event_handler("on_user_speech_stopped_for_turn")
async def on_user_speech_stopped_for_turn(_observer, turn_number: int, _data):
callback_timestamp = _now_iso()
await self.record_user_stopped_speaking(turn_number, callback_timestamp)
@observer.event_handler("on_bot_started_speaking")
async def on_bot_started_speaking(_observer, turn_number: int, _data):
await self.record_bot_started_speaking(turn_number)
@observer.event_handler("on_bot_stopped_speaking")
async def on_bot_stopped_speaking(_observer, turn_number: int, _data):
await self.record_bot_stopped_speaking(turn_number)
def _state(self, turn_id: int) -> _TurnTranscriptState:
state = self._states.get(turn_id)
if state is None:
state = _TurnTranscriptState(turn_id=turn_id)
self._states[turn_id] = state
return state
async def record_turn_started(self, turn_id: int) -> None:
async with self._lock:
self._state(turn_id)
if self._active_turn_id is None or turn_id >= self._active_turn_id:
self._active_turn_id = turn_id
self._logs_buffer.set_current_turn(turn_id)
async def record_turn_ended(self, turn_id: int, *, interrupted: bool) -> None:
async with self._lock:
state = self._state(turn_id)
state.ended = True
state.interrupted = interrupted
if self._active_turn_id == turn_id:
self._active_turn_id = None
await self._emit_ready_sides(state)
async def record_user_started_speaking(
self, turn_id: int, timestamp: str | None = None
) -> None:
async with self._lock:
state = self._state(turn_id)
side = state.user
previous_start = side.speech_start_timestamp
candidate_start = timestamp or _now_iso()
side.speech_start_timestamp = (
min(previous_start, candidate_start)
if previous_start is not None
else candidate_start
)
side.speaking = True
async def record_user_stopped_speaking(
self, turn_id: int, timestamp: str | None = None
) -> None:
async with self._lock:
side = self._state(turn_id).user
previous_end = side.speech_end_timestamp
candidate_end = timestamp or _now_iso()
side.speech_end_timestamp = (
max(previous_end, candidate_end)
if previous_end is not None
else candidate_end
)
side.speaking = False
async def record_bot_started_speaking(
self, turn_id: int, timestamp: str | None = None
) -> None:
async with self._lock:
side = self._state(turn_id).assistant
if side.speech_start_timestamp is None:
side.speech_start_timestamp = timestamp or _now_iso()
side.speaking = True
async def record_bot_stopped_speaking(
self, turn_id: int, timestamp: str | None = None
) -> None:
async with self._lock:
state = self._state(turn_id)
side = state.assistant
side.speech_end_timestamp = timestamp or _now_iso()
side.speaking = False
await self._emit_ready_sides(state)
async def record_user_transcript(
self,
*,
text: str,
timestamp: str | None,
end_timestamp: str | None = None,
event_timestamp: str | None = None,
) -> None:
async with self._lock:
state = self._select_user_turn()
side = state.user
first_text = side.text is None
side.text = text if first_text else f"{side.text}\n{text}"
if first_text:
side.transcript_timestamp = timestamp
self._capture_node(side)
side.event_timestamp = event_timestamp or _now_iso()
if end_timestamp and not side.speech_end_timestamp:
side.speech_end_timestamp = end_timestamp
await self._emit_ready_sides(state)
async def record_assistant_transcript(
self,
*,
text: str,
timestamp: str | None,
end_timestamp: str | None = None,
event_timestamp: str | None = None,
) -> None:
async with self._lock:
state = self._select_assistant_turn()
side = state.assistant
first_text = side.text is None
side.text = text if first_text else f"{side.text}\n{text}"
if first_text:
side.transcript_timestamp = timestamp
self._capture_node(side)
side.event_timestamp = event_timestamp or _now_iso()
if end_timestamp and not side.speech_end_timestamp:
side.speech_end_timestamp = end_timestamp
await self._emit_ready_sides(state)
def _select_user_turn(self) -> _TurnTranscriptState:
if self._active_turn_id is not None:
active = self._state(self._active_turn_id)
if active.user.text is None:
return active
candidates = [
state
for state in self._states.values()
if state.user.speech_start_timestamp and state.user.text is None
]
if candidates:
return min(candidates, key=lambda state: state.turn_id)
if self._states:
return max(self._states.values(), key=lambda state: state.turn_id)
return self._state(1)
def _select_assistant_turn(self) -> _TurnTranscriptState:
candidates = [
state
for state in self._states.values()
if state.assistant.speech_start_timestamp and state.assistant.text is None
]
interrupted = [
state for state in candidates if state.ended and state.interrupted
]
if interrupted:
return min(interrupted, key=lambda state: state.turn_id)
if self._active_turn_id is not None:
active = self._state(self._active_turn_id)
if active.assistant.text is None:
return active
if candidates:
return min(candidates, key=lambda state: state.turn_id)
if self._states:
return max(self._states.values(), key=lambda state: state.turn_id)
return self._state(1)
def _capture_node(self, side: _TranscriptSide) -> None:
side.node_id = self._logs_buffer.current_node_id
side.node_name = self._logs_buffer.current_node_name
async def _emit_ready_sides(self, state: _TurnTranscriptState) -> None:
if not state.ended:
return
await self._emit_user(state)
if not state.assistant.speaking:
await self._emit_assistant(state)
async def _emit_user(self, state: _TurnTranscriptState) -> None:
side = state.user
if side.emitted or not side.text:
return
event = build_user_transcription_event(
text=side.text,
final=True,
timestamp=side.speech_start_timestamp or side.transcript_timestamp,
end_timestamp=side.speech_end_timestamp,
)
await self._append(state, side, event)
async def _emit_assistant(self, state: _TurnTranscriptState) -> None:
side = state.assistant
if side.emitted or not side.text:
return
event = build_bot_text_event(
text=side.text,
timestamp=side.speech_start_timestamp or side.transcript_timestamp,
end_timestamp=side.speech_end_timestamp,
)
await self._append(state, side, event)
async def _append(
self, state: _TurnTranscriptState, side: _TranscriptSide, event: dict
) -> None:
await self._logs_buffer.append(
event,
timestamp=side.event_timestamp,
turn=state.turn_id,
node_id=side.node_id,
node_name=side.node_name,
use_current_node=False,
)
side.emitted = True
async def flush(self) -> None:
"""Emit any remaining transcript text without inventing missing timing."""
async with self._lock:
for state in sorted(self._states.values(), key=lambda item: item.turn_id):
state.ended = True
state.user.speaking = False
state.assistant.speaking = False
await self._emit_ready_sides(state)

View file

@ -34,7 +34,7 @@ def test_stamp_and_sort_realtime_feedback_events():
previous_node_id=None,
previous_node_name=None,
),
timestamp="2026-01-01T00:00:03+00:00",
timestamp="2026-01-01T00:00:01+00:00",
turn=0,
node_id="node-1",
node_name="Greeting",
@ -42,7 +42,9 @@ def test_stamp_and_sort_realtime_feedback_events():
bot_text = stamp_realtime_feedback_event(
build_bot_text_event(
text="Hello there",
timestamp="2026-01-01T00:00:01+00:00",
# Deliberately earlier than the node's event timestamp: ordering
# follows the top-level event timestamp, not payload speech time.
timestamp="2026-01-01T00:00:00+00:00",
),
timestamp="2026-01-01T00:00:02+00:00",
turn=0,
@ -50,7 +52,7 @@ def test_stamp_and_sort_realtime_feedback_events():
events = sorted([node_transition, bot_text], key=realtime_feedback_event_sort_key)
assert events == [bot_text, node_transition]
assert events == [node_transition, bot_text]
assert node_transition["node_id"] == "node-1"
assert node_transition["node_name"] == "Greeting"

View file

@ -3,14 +3,8 @@ from types import SimpleNamespace
import pytest
from pipecat.frames.frames import (
BotStartedSpeakingFrame,
BotStoppedSpeakingFrame,
TranscriptionFrame,
TTSTextFrame,
UserStartedSpeakingFrame,
UserStoppedSpeakingFrame,
VADUserStartedSpeakingFrame,
VADUserStoppedSpeakingFrame,
)
from pipecat.observers.base_observer import FramePushed
from pipecat.processors.frame_processor import FrameDirection
@ -22,6 +16,7 @@ from api.services.pipecat.realtime_feedback_observer import (
RealtimeFeedbackObserver,
register_turn_log_handlers,
)
from api.services.pipecat.transcript_log_coordinator import TranscriptLogCoordinator
class _FakeAggregator:
@ -129,14 +124,16 @@ async def test_observer_waits_for_tts_text_from_output_transport():
@pytest.mark.asyncio
async def test_turn_log_handlers_persist_user_message_added_events():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
coordinator = TranscriptLogCoordinator(logs_buffer)
user_aggregator = _FakeAggregator()
assistant_aggregator = _FakeAggregator()
register_turn_log_handlers(logs_buffer, user_aggregator, assistant_aggregator)
register_turn_log_handlers(coordinator, user_aggregator, assistant_aggregator)
assert "on_user_turn_message_added" in user_aggregator.handlers
assert "on_user_turn_stopped" not in user_aggregator.handlers
logs_buffer.set_current_node("node-a", "Node A")
await user_aggregator.handlers["on_user_turn_message_added"](
user_aggregator,
SimpleNamespace(
@ -144,6 +141,8 @@ async def test_turn_log_handlers_persist_user_message_added_events():
timestamp="2026-01-01T00:00:00+00:00",
),
)
logs_buffer.set_current_node("node-b", "Node B")
await coordinator.record_turn_ended(1, interrupted=False)
events = logs_buffer.get_events()
assert len(events) == 1
@ -154,26 +153,22 @@ async def test_turn_log_handlers_persist_user_message_added_events():
"timestamp": "2026-01-01T00:00:00+00:00",
}
assert events[0]["turn"] == 1
assert events[0]["node_id"] == "node-a"
assert events[0]["node_name"] == "Node A"
@pytest.mark.asyncio
async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript_events():
async def ws_sender(_message):
pass
async def test_coordinator_attaches_speaking_intervals_to_logged_transcript_events():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
observer = RealtimeFeedbackObserver(ws_sender=ws_sender, logs_buffer=logs_buffer)
coordinator = TranscriptLogCoordinator(logs_buffer)
user_aggregator = _FakeAggregator()
assistant_aggregator = _FakeAggregator()
register_turn_log_handlers(logs_buffer, user_aggregator, assistant_aggregator)
register_turn_log_handlers(coordinator, user_aggregator, assistant_aggregator)
await observer.on_push_frame(
_frame_pushed(UserStartedSpeakingFrame(), FrameDirection.DOWNSTREAM)
)
await observer.on_push_frame(
_frame_pushed(UserStoppedSpeakingFrame(), FrameDirection.DOWNSTREAM)
)
await coordinator.record_turn_started(1)
await coordinator.record_user_started_speaking(1)
await coordinator.record_user_stopped_speaking(1)
await user_aggregator.handlers["on_user_turn_message_added"](
user_aggregator,
SimpleNamespace(
@ -182,9 +177,7 @@ async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript
),
)
await observer.on_push_frame(
_frame_pushed(BotStartedSpeakingFrame(), FrameDirection.DOWNSTREAM)
)
await coordinator.record_bot_started_speaking(1)
await assistant_aggregator.handlers["on_assistant_turn_stopped"](
assistant_aggregator,
SimpleNamespace(
@ -192,9 +185,15 @@ async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript
timestamp="aggregator-bot-start",
),
)
await observer.on_push_frame(
_frame_pushed(BotStoppedSpeakingFrame(), FrameDirection.DOWNSTREAM)
await assistant_aggregator.handlers["on_assistant_turn_stopped"](
assistant_aggregator,
SimpleNamespace(
content="You're welcome",
timestamp="second-aggregator-bot-start",
),
)
await coordinator.record_bot_stopped_speaking(1)
await coordinator.record_turn_ended(1, interrupted=False)
user_event, bot_event = [
event
@ -202,6 +201,8 @@ async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript
if event["type"] in {"rtf-user-transcription", "rtf-bot-text"}
]
assert user_event["turn"] == 1
assert bot_event["turn"] == 1
assert user_event["payload"]["timestamp"] != "aggregator-user-start"
assert re.match(
r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}\+00:00$",
@ -209,6 +210,7 @@ async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript
)
assert user_event["payload"]["end_timestamp"]
assert bot_event["payload"]["timestamp"] != "aggregator-bot-start"
assert bot_event["payload"]["text"] == "Thank you\nYou're welcome"
assert re.match(
r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}\+00:00$",
bot_event["payload"]["timestamp"],
@ -217,76 +219,136 @@ async def test_observer_attaches_backend_speaking_intervals_to_logged_transcript
@pytest.mark.asyncio
async def test_observer_uses_vad_user_speech_times_over_turn_closure_times():
async def ws_sender(_message):
pass
async def test_user_speaking_frames_define_full_multi_segment_turn_envelope():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
observer = RealtimeFeedbackObserver(ws_sender=ws_sender, logs_buffer=logs_buffer)
coordinator = TranscriptLogCoordinator(logs_buffer)
user_aggregator = _FakeAggregator()
assistant_aggregator = _FakeAggregator()
register_turn_log_handlers(logs_buffer, user_aggregator, assistant_aggregator)
await observer.on_push_frame(
_frame_pushed(
VADUserStartedSpeakingFrame(start_secs=0.2, timestamp=1000.2),
FrameDirection.DOWNSTREAM,
)
)
await observer.on_push_frame(
_frame_pushed(
VADUserStoppedSpeakingFrame(stop_secs=0.5, timestamp=1002.5),
FrameDirection.DOWNSTREAM,
)
)
await observer.on_push_frame(
_frame_pushed(UserStoppedSpeakingFrame(), FrameDirection.DOWNSTREAM)
)
register_turn_log_handlers(coordinator, user_aggregator, assistant_aggregator)
await coordinator.record_turn_started(2)
await coordinator.record_user_started_speaking(2, "2026-07-14T09:55:22.132+00:00")
await coordinator.record_user_stopped_speaking(2, "2026-07-14T09:55:27.713+00:00")
await user_aggregator.handlers["on_user_turn_message_added"](
user_aggregator,
SimpleNamespace(content="Hello", timestamp="aggregator-user-start"),
SimpleNamespace(
content="Yeah, yeah. I'm just like,",
timestamp="2026-07-14T09:55:22.132+00:00",
),
)
# The user resumes before the bot speaks, so this remains canonical Turn 2.
await coordinator.record_user_started_speaking(2, "2026-07-14T09:55:28.393+00:00")
await coordinator.record_user_stopped_speaking(2, "2026-07-14T09:55:29.994+00:00")
await user_aggregator.handlers["on_user_turn_message_added"](
user_aggregator,
SimpleNamespace(
content="what to get",
timestamp="2026-07-14T09:55:28.393+00:00",
),
)
await coordinator.record_turn_ended(2, interrupted=False)
user_event = logs_buffer.get_events()[0]
assert user_event["payload"]["timestamp"] == "1970-01-01T00:16:40.000+00:00"
assert user_event["payload"]["end_timestamp"] == "1970-01-01T00:16:42.000+00:00"
assert user_event["turn"] == 2
assert user_event["payload"] == {
"text": "Yeah, yeah. I'm just like,\nwhat to get",
"final": True,
"timestamp": "2026-07-14T09:55:22.132+00:00",
"end_timestamp": "2026-07-14T09:55:29.994+00:00",
}
@pytest.mark.asyncio
async def test_completed_bot_speech_interval_is_not_reused_for_next_pre_playback_text():
async def test_appended_events_are_not_mutated_by_later_turn_activity():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
first = {"type": "rtf-bot-text", "payload": {"text": "First"}}
logs_buffer.mark_bot_started_speaking("2026-01-01T00:00:01.000+00:00")
await logs_buffer.append({"type": "rtf-bot-text", "payload": {"text": "First"}})
logs_buffer.mark_bot_stopped_speaking("2026-01-01T00:00:02.000+00:00")
await logs_buffer.append(first, turn=1)
first["payload"]["text"] = "Mutated outside the buffer"
logs_buffer.set_current_turn(2)
await logs_buffer.append({"type": "rtf-bot-text", "payload": {"text": "Second"}})
second_event = logs_buffer.get_events()[-1]
assert second_event["payload"] == {"text": "Second"}
assert logs_buffer.get_events()[0]["payload"] == {"text": "First"}
@pytest.mark.asyncio
async def test_non_vad_user_turn_after_completed_vad_turn_gets_fresh_timestamps():
async def test_stored_events_are_sorted_by_event_timestamp_not_payload_timestamp():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
logs_buffer.mark_user_started_speaking(
"2026-01-01T00:00:01.000+00:00", from_vad=True
)
logs_buffer.mark_user_stopped_speaking(
"2026-01-01T00:00:02.000+00:00", from_vad=True
await logs_buffer.append(
{
"type": "rtf-bot-text",
"payload": {"text": "Speech started first", "timestamp": "payload-1"},
},
timestamp="2026-01-01T00:00:02.000+00:00",
turn=1,
)
await logs_buffer.append(
{"type": "rtf-user-transcription", "payload": {"text": "First", "final": True}}
{
"type": "rtf-node-transition",
"payload": {"timestamp": "payload-2"},
},
timestamp="2026-01-01T00:00:01.000+00:00",
turn=1,
)
logs_buffer.mark_user_started_speaking("2026-01-01T00:00:10.000+00:00")
logs_buffer.mark_user_stopped_speaking("2026-01-01T00:00:12.000+00:00")
await logs_buffer.append(
{"type": "rtf-user-transcription", "payload": {"text": "Second", "final": True}}
)
assert [event["timestamp"] for event in logs_buffer.get_events()] == [
"2026-01-01T00:00:01.000+00:00",
"2026-01-01T00:00:02.000+00:00",
]
@pytest.mark.asyncio
async def test_completed_user_turn_does_not_reuse_speaking_frame_timestamps():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=123)
coordinator = TranscriptLogCoordinator(logs_buffer)
await coordinator.record_turn_started(1)
await coordinator.record_user_started_speaking(1, "2026-01-01T00:00:01.000+00:00")
await coordinator.record_user_stopped_speaking(1, "2026-01-01T00:00:02.000+00:00")
await coordinator.record_user_transcript(text="First", timestamp=None)
await coordinator.record_turn_ended(1, interrupted=False)
await coordinator.record_turn_started(2)
await coordinator.record_user_started_speaking(2, "2026-01-01T00:00:10.000+00:00")
await coordinator.record_user_stopped_speaking(2, "2026-01-01T00:00:12.000+00:00")
await coordinator.record_user_transcript(text="Second", timestamp=None)
await coordinator.record_turn_ended(2, interrupted=False)
second_event = logs_buffer.get_events()[-1]
assert second_event["payload"]["timestamp"] == "2026-01-01T00:00:10.000+00:00"
assert second_event["payload"]["end_timestamp"] == "2026-01-01T00:00:12.000+00:00"
@pytest.mark.asyncio
async def test_interrupted_bot_transcript_keeps_the_interrupted_turn_interval():
logs_buffer = InMemoryLogsBuffer(workflow_run_id=2122)
coordinator = TranscriptLogCoordinator(logs_buffer)
await coordinator.record_turn_started(2)
await coordinator.record_bot_started_speaking(2, "2026-07-14T13:33:02.254+00:00")
# The user interrupts: logical Turn 2 ends and Turn 3 starts before the
# output transport reports that Turn 2's audio has physically stopped.
await coordinator.record_turn_ended(2, interrupted=True)
await coordinator.record_turn_started(3)
await coordinator.record_bot_stopped_speaking(2, "2026-07-14T13:33:03.817+00:00")
await coordinator.record_assistant_transcript(
text="A minivan, too easy,",
timestamp="2026-07-14T13:33:06.654+00:00",
event_timestamp="2026-07-14T13:33:03.819+00:00",
)
[event] = logs_buffer.get_events()
assert event["type"] == "rtf-bot-text"
assert event["timestamp"] == "2026-07-14T13:33:03.819+00:00"
assert event["turn"] == 2
assert event["payload"] == {
"text": "A minivan, too easy,",
"timestamp": "2026-07-14T13:33:02.254+00:00",
"end_timestamp": "2026-07-14T13:33:03.817+00:00",
}
await coordinator.record_bot_started_speaking(3, "2026-07-14T13:33:06.654+00:00")
assert event["payload"]["timestamp"] == "2026-07-14T13:33:02.254+00:00"