mirror of
https://github.com/BerriAI/litellm.git
synced 2026-10-28 06:23:07 +00:00
* 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>
150 lines
5.3 KiB
Python
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)]
|