litellm/tests/unit/interactions/test_interactions_streaming_iterator.py
Max Azatian 5145250d83
fix(langfuse_otel)!: send the completion start time (#45597)
* fix(langfuse_otel): send the completion start time

langfuse_otel never set langfuse.observation.completion_start_time, so
Langfuse showed no time to first token for any call, streamed or not.
The legacy langfuse callback already sends kwargs["completion_start_time"].
Send the same value as an ISO timestamp with an explicit offset.

* fix(langfuse_otel): type kwargs and test against a real span

Type the kwargs of _set_langfuse_specific_attributes as dict[str, Any],
the declared type of model_call_details, so the new completion start time
read adds no unknown-type errors. The tests now check a real SDK span
instead of patching safe_set_attribute, and the parameter is typed.

* fix(otel): send the completion start time from the v2 Langfuse mapper

With LITELLM_OTEL_V2 the langfuse_otel spans come from LangfuseMapper,
which had no completion start time either. Carry the payload's
completionStartTime on LLMCallSpanData for streamed calls, the same calls
that get time_to_first_chunk_seconds, and map it to
langfuse.observation.completion_start_time.

* fix(langfuse_otel): take the logging kwargs as a read-only Mapping

The new kwargs annotation tripped LIT001. Both helpers only read the
logging kwargs, so type them Mapping[str, Any] instead of dict.

* fix(langfuse_otel): time /v1/messages streams from the call start and send the V2 completion start time like the default emitter

* fix(langfuse_otel): time Gemini, Interactions and A2A streams from their first chunk and send the start time as JSON

The native Gemini, Interactions and A2A streams never recorded a first chunk, so with
completion_start_time now sent both emitters showed TTFT equal to latency on them. They
now record it, and Gemini and Interactions take the call's start time like /v1/messages.

Both emitters send the completion start time as a JSON string, the form the Langfuse SDK
and the langfuse callback send, through one serializer.

* fix(langfuse_otel): time A2A streams from the call start and record a cached replay's first event

A2A streams took their start time when the iterator was built, so their latency left out
the work before it. They now use the call's start time like every other route.

Cached /v1/messages stream replays recorded no first event, so their time to first token
fell back to the end time. The replay now records it on the first event it yields.

The tests use the real Interactions config and typed logger hooks.

* fix(a2a): time streamed A2A calls from before the agent card fetch and make the cached replay test clock-free

* test(a2a): type the card fetch test and stop rebinding the seed helper's recorder

* test(otel): expect completion_start_time and cache_hit in the B3 span keys

---------

Co-authored-by: mateo-berri <277851410+mateo-berri@users.noreply.github.com>
2026-10-20 13:52:26 +00:00

150 lines
5.3 KiB
Python

"""
Regression test for LIT-4210: completing an async Interactions API stream must
not run the sync success_handler on the thread-pool executor concurrently with
async_success_handler (cross-thread pydantic mutation segfaults pydantic-core).
"""
import asyncio
import json
import time
from datetime import datetime
from typing import Final
import httpx
import pytest
import litellm
from litellm.integrations.custom_logger import CustomLogger
from litellm.interactions import streaming_iterator as interactions_streaming_iterator_module
from litellm.interactions.streaming_iterator import InteractionsAPIStreamingIterator
from litellm.litellm_core_utils import thread_pool_executor as thread_pool_executor_module
from litellm.litellm_core_utils.litellm_logging import Logging as LitellmLogging
from litellm.llms.gemini.interactions.transformation import GoogleAIStudioInteractionsConfig
from litellm.types.interactions import InteractionsAPIStreamingResponse
class RecordingCustomLogger(CustomLogger):
def __init__(self):
super().__init__()
self.async_hook_fired = False
async def async_log_success_event(self, kwargs, response_obj, start_time, end_time):
self.async_hook_fired = True
async def async_log_stream_event(self, kwargs, response_obj, start_time, end_time):
self.async_hook_fired = True
class RecordingExecutor:
def __init__(self, inner):
self._inner = inner
self.submits: list = []
def submit(self, fn, *args, **kwargs):
self.submits.append(fn)
return self._inner.submit(fn, *args, **kwargs)
def submitted_for(self, logging_obj) -> list:
return [fn for fn in self.submits if getattr(fn, "__self__", None) is logging_obj]
@pytest.fixture(autouse=True)
def _isolate_callbacks():
saved = (
litellm.callbacks,
litellm.success_callback,
litellm._async_success_callback,
litellm.failure_callback,
litellm._async_failure_callback,
)
yield
(
litellm.callbacks,
litellm.success_callback,
litellm._async_success_callback,
litellm.failure_callback,
litellm._async_failure_callback,
) = saved
@pytest.mark.asyncio
async def test_custom_logger_only_never_submits_sync_success_handler(monkeypatch):
recording_executor = RecordingExecutor(thread_pool_executor_module.executor)
monkeypatch.setattr(thread_pool_executor_module, "executor", recording_executor)
monkeypatch.setattr(interactions_streaming_iterator_module, "executor", recording_executor)
recorder = RecordingCustomLogger()
litellm.success_callback = [recorder]
litellm._async_success_callback = [recorder]
logging_obj = LitellmLogging(
model="gemini/gemini-3-pro-preview",
messages=[{"role": "user", "content": "hi"}],
stream=True,
call_type="ainteraction",
start_time=time.time(),
litellm_call_id="lit-4210-test",
function_id="lit-4210-test",
)
iterator = InteractionsAPIStreamingIterator(
response=httpx.Response(200),
model="gemini/gemini-3-pro-preview",
interactions_api_config=None,
logging_obj=logging_obj,
)
iterator.completed_response = InteractionsAPIStreamingResponse()
existing_tasks = asyncio.all_tasks()
iterator._handle_logging_completed_response()
spawned_tasks = asyncio.all_tasks() - existing_tasks
await asyncio.wait_for(asyncio.gather(*spawned_tasks, return_exceptions=True), timeout=5)
assert recorder.async_hook_fired is True
assert recording_executor.submitted_for(logging_obj) == []
class _SuccessRecorder(CustomLogger):
def __init__(self):
super().__init__()
self.logged: list[tuple[datetime, object]] = []
async def async_log_success_event(
self, kwargs: dict[str, object], response_obj: object, start_time: datetime, end_time: datetime
) -> None:
self.logged.append((start_time, kwargs.get("completion_start_time")))
@pytest.mark.asyncio
async def test_stream_logs_its_first_event_time_measured_from_the_call_start():
call_start: Final = datetime(2026, 10, 9, 12, 0, 0)
recorder: Final = _SuccessRecorder()
logging_obj: Final = LitellmLogging(
model="gemini/gemini-3-pro-preview",
messages=[{"role": "user", "content": "hi"}],
stream=True,
call_type="ainteraction",
start_time=call_start,
litellm_call_id="interactions-stream",
function_id="interactions-stream",
dynamic_async_success_callbacks=[recorder],
)
events: Final = (
{"event_type": "step.delta", "id": "interaction-1"},
{"event_type": "interaction.completed", "id": "interaction-1", "status": "completed"},
)
response: Final = httpx.Response(200, content="".join(f"data: {json.dumps(e)}\n\n" for e in events).encode())
iterator: Final = InteractionsAPIStreamingIterator(
response=response,
model="gemini/gemini-3-pro-preview",
interactions_api_config=GoogleAIStudioInteractionsConfig(),
logging_obj=logging_obj,
)
tasks_before: Final = asyncio.all_tasks()
_ = await iterator.__anext__()
first_event_at: Final = logging_obj.completion_start_time
_ = [event async for event in iterator]
await asyncio.gather(*(asyncio.all_tasks() - tasks_before))
assert first_event_at is not None
assert recorder.logged == [(call_start, first_event_at)]