litellm/tests/test_litellm/responses/test_streaming_iterator.py

630 lines
22 KiB
Python

"""Regression tests for LIT-4185 — /v1/responses streaming must stamp
completion_start_time on the first chunk so downstream TTFT consumers
(Prometheus, OTEL, SpendLogs completionStartTime) do not fall back to
completion_start_time = end_time."""
import json
from datetime import datetime
from typing import Optional
from unittest.mock import Mock, patch
import httpx
import pytest
from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLoggingObj
from litellm.llms.base_llm.responses.transformation import BaseResponsesAPIConfig
from litellm.responses.streaming_iterator import (
ResponsesAPIStreamingIterator,
SyncResponsesAPIStreamingIterator,
)
from litellm.types.llms.openai import (
ResponseAPIUsage,
ResponseCompletedEvent,
ResponsesAPIResponse,
ResponsesAPIStreamEvents,
)
def _sse_event(payload: dict) -> bytes:
return f"data: {json.dumps(payload)}\n\n".encode("utf-8")
def _mock_config() -> Mock:
mock_config = Mock(spec=BaseResponsesAPIConfig)
mock_responses_api_response = Mock(spec=ResponsesAPIResponse)
mock_responses_api_response.id = "resp_ttft"
def _transform(model, parsed_chunk, logging_obj):
evt_type = parsed_chunk.get("type")
if evt_type == "response.completed":
completed = Mock(spec=ResponseCompletedEvent)
completed.type = ResponsesAPIStreamEvents.RESPONSE_COMPLETED
completed.response = mock_responses_api_response
return completed
stub = Mock()
stub.type = evt_type
return stub
mock_config.transform_streaming_response.side_effect = _transform
return mock_config
def _make_iterator(
*,
sse_events: list[bytes],
logging_obj: LiteLLMLoggingObj,
trailing_error: Optional[Exception] = None,
) -> ResponsesAPIStreamingIterator:
async def aiter_bytes():
for evt in sse_events:
yield evt
if trailing_error is not None:
raise trailing_error
mock_response = Mock()
mock_response.headers = {}
mock_response.aiter_bytes = aiter_bytes
return ResponsesAPIStreamingIterator(
response=mock_response,
model="gpt-4o-mini",
responses_api_provider_config=_mock_config(),
logging_obj=logging_obj,
litellm_metadata={},
custom_llm_provider="openai",
)
def _make_sync_iterator(
*,
sse_events: list[bytes],
logging_obj: LiteLLMLoggingObj,
trailing_error: Optional[Exception] = None,
) -> SyncResponsesAPIStreamingIterator:
def iter_bytes():
for evt in sse_events:
yield evt
if trailing_error is not None:
raise trailing_error
mock_response = Mock()
mock_response.headers = {}
mock_response.iter_bytes = iter_bytes
return SyncResponsesAPIStreamingIterator(
response=mock_response,
model="gpt-4o-mini",
responses_api_provider_config=_mock_config(),
logging_obj=logging_obj,
litellm_metadata={},
custom_llm_provider="openai",
)
def _logging_obj_stub() -> Mock:
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj.completion_start_time = None
logging_obj.model_call_details = {"litellm_params": {}}
return logging_obj
@pytest.mark.asyncio
async def test_responses_streaming_stamps_completion_start_time_on_first_chunk():
"""Without the fix, `logging_obj.completion_start_time` stays None across the
entire stream and _success_handler_helper_fn falls back to end_time — collapsing
the reported TTFT to full generation time."""
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj.completion_start_time = None
logging_obj.model_call_details = {"litellm_params": {}}
stamped: list[datetime] = []
def _update(*, completion_start_time):
stamped.append(completion_start_time)
logging_obj.completion_start_time = completion_start_time
logging_obj.model_call_details["completion_start_time"] = completion_start_time
logging_obj._update_completion_start_time.side_effect = _update
iterator = _make_iterator(
sse_events=[
_sse_event({"type": "response.created"}),
_sse_event({"type": "response.output_text.delta", "delta": "hi"}),
_sse_event({"type": "response.completed"}),
],
logging_obj=logging_obj,
)
async for _ in iterator:
pass
assert len(stamped) == 1, (
f"Expected exactly one first-chunk stamp; got {len(stamped)}. "
"Later chunks must not re-stamp completion_start_time."
)
assert isinstance(stamped[0], datetime)
@pytest.mark.asyncio
async def test_responses_streaming_does_not_reset_prior_completion_start_time():
"""If `completion_start_time` is already set (e.g. by an outer wrapper), the
iterator must not overwrite it — otherwise TTFT would collapse to
time-to-last-chunk under contention."""
prior = datetime(2020, 1, 1, 0, 0, 0)
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj.completion_start_time = prior
logging_obj.model_call_details = {"litellm_params": {}}
iterator = _make_iterator(
sse_events=[
_sse_event({"type": "response.created"}),
_sse_event({"type": "response.completed"}),
],
logging_obj=logging_obj,
)
async for _ in iterator:
pass
logging_obj._update_completion_start_time.assert_not_called()
assert logging_obj.completion_start_time == prior
_COMPLETE_STREAM_EVENTS = [
_sse_event({"type": "response.created"}),
_sse_event({"type": "response.output_text.delta", "delta": "hi"}),
_sse_event({"type": "response.completed"}),
]
_TRAILING_ERRORS = [
httpx.ReadError("Response payload is not completed"),
httpx.RemoteProtocolError("peer closed connection without sending complete message body"),
]
@pytest.mark.asyncio
@pytest.mark.parametrize("trailing_error", _TRAILING_ERRORS, ids=type)
async def test_transport_error_after_completed_event_ends_stream_cleanly(trailing_error):
"""A sloppy connection close after `response.completed` must not turn a
complete stream into an error (regression guard for the transport no longer
swallowing ClientPayloadError/TransferEncodingError)."""
iterator = _make_iterator(
sse_events=_COMPLETE_STREAM_EVENTS,
logging_obj=_logging_obj_stub(),
trailing_error=trailing_error,
)
seen = [event.type async for event in iterator]
assert ResponsesAPIStreamEvents.RESPONSE_COMPLETED in seen
@pytest.mark.asyncio
async def test_transport_error_before_completed_event_raises():
"""A connection lost before any terminal event is a real failure and must
surface, not end the stream as if it completed."""
iterator = _make_iterator(
sse_events=_COMPLETE_STREAM_EVENTS[:-1],
logging_obj=_logging_obj_stub(),
trailing_error=httpx.ReadError("Response payload is not completed"),
)
with pytest.raises(httpx.ReadError):
async for _ in iterator:
pass
@pytest.mark.parametrize("trailing_error", _TRAILING_ERRORS, ids=type)
def test_sync_transport_error_after_completed_event_ends_stream_cleanly(trailing_error):
iterator = _make_sync_iterator(
sse_events=_COMPLETE_STREAM_EVENTS,
logging_obj=_logging_obj_stub(),
trailing_error=trailing_error,
)
seen = [event.type for event in iterator]
assert ResponsesAPIStreamEvents.RESPONSE_COMPLETED in seen
def test_sync_transport_error_before_completed_event_raises():
iterator = _make_sync_iterator(
sse_events=_COMPLETE_STREAM_EVENTS[:-1],
logging_obj=_logging_obj_stub(),
trailing_error=httpx.ReadError("Response payload is not completed"),
)
with pytest.raises(httpx.ReadError):
for _ in iterator:
pass
def test_stream_cache_write_completes_when_asyncio_run_closes_the_loop(monkeypatch):
"""
Regression test for LIT-6184 on the /v1/responses streaming surface: the
completed-stream cache write was dispatched as a bare fire-and-forget task,
so asyncio.run cancelled it at loop close before the write landed. The
write must survive loop shutdown just like the chat-completions one.
"""
import asyncio
from types import SimpleNamespace
import litellm
from litellm.types.utils import CallTypes
writes = []
class _SlowWriteCache:
async def async_add_cache(self, result, dynamic_cache_object=None, **kwargs):
await asyncio.sleep(0.2)
writes.append(result)
def add_cache(self, *args, **kwargs):
raise AssertionError("sync write must not run on the async path")
caching_handler = SimpleNamespace(
request_kwargs={
"model": "test-model",
"input": "hello",
"stream": True,
"caching": True,
"metadata": None,
"custom_llm_provider": "openai",
},
preset_cache_key="responses-stream-cache-key",
original_function=litellm.aresponses,
dual_cache=None,
_should_store_result_in_cache=lambda original_function, kwargs: True,
)
logging_obj = SimpleNamespace(
model_call_details={"litellm_params": {}},
_llm_caching_handler=caching_handler,
)
iterator = ResponsesAPIStreamingIterator(
response=httpx.Response(200),
model="test-model",
responses_api_provider_config=Mock(spec=BaseResponsesAPIConfig),
logging_obj=logging_obj,
request_data=caching_handler.request_kwargs,
call_type=CallTypes.aresponses.value,
)
iterator.completed_response = ResponseCompletedEvent(
type=ResponsesAPIStreamEvents.RESPONSE_COMPLETED,
response=ResponsesAPIResponse(
id="resp_lit6184",
created_at=int(datetime.now().timestamp()),
status="completed",
model="test-model",
object="response",
output=[],
),
)
monkeypatch.setattr(litellm, "cache", _SlowWriteCache())
async def _short_lived_script():
iterator._persist_completed_response_to_cache(is_async=True)
asyncio.run(_short_lived_script())
assert len(writes) == 1
def test_run_post_success_hooks_does_not_report_generation_time_as_overhead():
"""LIT-5466: the provider call is timed to first byte, so at stream completion the total minus
that duration is token generation, not LiteLLM overhead."""
logging_obj = _logging_obj_stub()
logging_obj.model_call_details = {"litellm_params": {}, "llm_api_duration_ms": 200.0}
logging_obj.caching_details = None
class _CompletedEvent:
def __init__(self) -> None:
self._hidden_params: dict = {}
iterator = _make_iterator(sse_events=[], logging_obj=logging_obj)
iterator.completed_response = _CompletedEvent()
iterator.start_time = datetime(2025, 1, 1, 0, 0, 0)
iterator._run_post_success_hooks(datetime(2025, 1, 1, 0, 0, 10))
assert iterator.completed_response._hidden_params["_response_ms"] == 10000.0
assert "litellm_overhead_time_ms" not in iterator.completed_response._hidden_params
def _responses_api_response_with_usage() -> ResponsesAPIResponse:
return ResponsesAPIResponse(
id="resp_lit6427",
created_at=int(datetime(2025, 1, 1).timestamp()),
status="completed",
model="mantle-claude",
object="response",
output=[],
usage=ResponseAPIUsage(input_tokens=20, output_tokens=60, total_tokens=80),
)
def test_stamp_responses_usage_cost_stamps_computed_cost():
from litellm.responses.streaming_iterator import _stamp_responses_usage_cost
response = _responses_api_response_with_usage()
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj._response_cost_calculator.return_value = 0.000704
_stamp_responses_usage_cost(response, logging_obj)
assert getattr(response.usage, "cost", None) == pytest.approx(0.000704)
logging_obj._response_cost_calculator.assert_called_once_with(result=response)
def test_stamp_responses_usage_cost_keeps_provider_reported_cost():
from litellm.responses.streaming_iterator import _stamp_responses_usage_cost
response = _responses_api_response_with_usage()
setattr(response.usage, "cost", 0.5)
logging_obj = Mock(spec=LiteLLMLoggingObj)
_stamp_responses_usage_cost(response, logging_obj)
assert getattr(response.usage, "cost", None) == pytest.approx(0.5)
logging_obj._response_cost_calculator.assert_not_called()
def _unvalidated_response_with_dict_usage(usage: dict) -> ResponsesAPIResponse:
return ResponsesAPIResponse.model_construct(
id="resp_lit7391",
created_at=int(datetime(2025, 1, 1).timestamp()),
status="completed",
model="perplexity/deepseek-v4-flash-0731",
object="response",
output=[],
truncation="",
usage=usage,
)
def test_stamp_responses_usage_cost_keeps_provider_cost_from_dict_usage():
from litellm.responses.streaming_iterator import _stamp_responses_usage_cost
response = _unvalidated_response_with_dict_usage(
{
"input_tokens": 29,
"output_tokens": 120,
"output_tokens_details": {"reasoning_tokens": 117},
"total_tokens": 149,
"cost": {"currency": "USD", "input_cost": 0, "output_cost": 3e-05, "total_cost": 3e-05},
}
)
logging_obj = Mock(spec=LiteLLMLoggingObj)
_stamp_responses_usage_cost(response, logging_obj)
assert isinstance(response.usage, ResponseAPIUsage)
assert response.usage.cost == pytest.approx(3e-05)
assert response.usage.output_tokens_details.reasoning_tokens == 117
logging_obj._response_cost_calculator.assert_not_called()
def test_stamp_responses_usage_cost_computes_cost_for_dict_usage_without_cost():
from litellm.responses.streaming_iterator import _stamp_responses_usage_cost
response = _unvalidated_response_with_dict_usage({"input_tokens": 29, "output_tokens": 120, "total_tokens": 149})
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj._response_cost_calculator.return_value = 0.000704
_stamp_responses_usage_cost(response, logging_obj)
assert isinstance(response.usage, ResponseAPIUsage)
assert response.usage.cost == pytest.approx(0.000704)
logging_obj._response_cost_calculator.assert_called_once_with(result=response)
def test_stamp_responses_usage_cost_survives_calculator_failure():
from litellm.responses.streaming_iterator import _stamp_responses_usage_cost
response = _responses_api_response_with_usage()
logging_obj = Mock(spec=LiteLLMLoggingObj)
logging_obj._response_cost_calculator.side_effect = RuntimeError("cost map unavailable")
_stamp_responses_usage_cost(response, logging_obj)
assert getattr(response.usage, "cost", None) is None
def _capture_dispatch(logged: list):
"""Record the object handed to the success handlers.
``Mock(spec=LiteLLMLoggingObj).dispatch_success_handlers`` is an AsyncMock whose side effect
only runs when the coroutine is awaited, so capture with a plain function instead.
"""
async def _noop() -> None:
return None
def _dispatch(result, **kwargs):
logged.append(result)
return _noop()
return _dispatch
def _headers_config(*, transform_hidden_params: Optional[dict] = None) -> Mock:
"""Config whose completed event carries a real ResponsesAPIResponse, so the logging copy
performs a genuine model_dump/model_validate round trip."""
mock_config = Mock(spec=BaseResponsesAPIConfig)
def _transform(model, parsed_chunk, logging_obj):
evt_type = parsed_chunk.get("type")
if evt_type != "response.completed":
stub = Mock()
stub.type = evt_type
return stub
response = ResponsesAPIResponse(
id="resp_headers",
created_at=1,
output=[],
parallel_tool_calls=False,
tool_choice="auto",
tools=[],
)
if transform_hidden_params is not None:
response._hidden_params.update(transform_hidden_params)
return ResponseCompletedEvent(
type=ResponsesAPIStreamEvents.RESPONSE_COMPLETED,
response=response,
)
mock_config.transform_streaming_response.side_effect = _transform
return mock_config
def _make_header_iterator(
*,
headers: dict,
config: Mock,
logging_obj: LiteLLMLoggingObj,
) -> ResponsesAPIStreamingIterator:
async def aiter_bytes():
yield _sse_event({"type": "response.completed"})
mock_response = Mock()
mock_response.headers = headers
mock_response.aiter_bytes = aiter_bytes
return ResponsesAPIStreamingIterator(
response=mock_response,
model="gpt-4o-mini",
responses_api_provider_config=config,
logging_obj=logging_obj,
litellm_metadata={},
custom_llm_provider="azure",
)
@pytest.mark.asyncio
async def test_streaming_logging_response_carries_provider_response_headers():
"""LIT-6055: the provider headers the iterator captured must reach the logged response, so
custom loggers can read Azure's apim-request-id from the callback payload."""
logging_obj = _logging_obj_stub()
logged: list[object] = []
logging_obj.dispatch_success_handlers = _capture_dispatch(logged)
logging_obj._on_deferred_stream_complete = None
iterator = _make_header_iterator(
headers={"apim-request-id": "azure-correlation-1", "x-ms-region": "East US 2"},
config=_headers_config(),
logging_obj=logging_obj,
)
async for _ in iterator:
pass
assert len(logged) == 1
hidden_params = logged[0].response._hidden_params
assert hidden_params["additional_headers"]["llm_provider-apim-request-id"] == "azure-correlation-1"
assert hidden_params["additional_headers"]["llm_provider-x-ms-region"] == "East US 2"
assert hidden_params["headers"]["apim-request-id"] == "azure-correlation-1"
# the proxy builds the client's response headers from the iterator's own dict, so the logged
# response must hold copies rather than alias it
assert hidden_params["additional_headers"] is not iterator._hidden_params["additional_headers"]
assert hidden_params["headers"] is not iterator._raw_response_headers
@pytest.mark.asyncio
async def test_streaming_logging_copy_preserves_transform_hidden_params():
"""LIT-6055: model_validate(model_dump()) drops pydantic private attributes, so headers a
provider transform already set on the response (fake_stream) must be re-applied."""
logging_obj = _logging_obj_stub()
logged: list[object] = []
logging_obj.dispatch_success_handlers = _capture_dispatch(logged)
logging_obj._on_deferred_stream_complete = None
iterator = _make_header_iterator(
headers={},
config=_headers_config(
transform_hidden_params={
"additional_headers": {"llm_provider-apim-request-id": "from-transform"},
"headers": {"apim-request-id": "from-transform"},
"response_cost": 0.5,
}
),
logging_obj=logging_obj,
)
async for _ in iterator:
pass
assert len(logged) == 1
hidden_params = logged[0].response._hidden_params
assert hidden_params["additional_headers"]["llm_provider-apim-request-id"] == "from-transform"
assert hidden_params["headers"]["apim-request-id"] == "from-transform"
assert iterator.completed_response is not logged[0]
# only the header keys travel: response_cost would short-circuit the cost calculator
assert "response_cost" not in hidden_params
@pytest.mark.asyncio
async def test_streaming_logging_copy_fallback_leaves_caller_event_untouched():
"""LIT-6055: when the logging copy falls back to the original event, the header restore must
not stamp logging-only state onto the object the caller is iterating."""
logging_obj = _logging_obj_stub()
logged: list[object] = []
logging_obj.dispatch_success_handlers = _capture_dispatch(logged)
logging_obj._on_deferred_stream_complete = None
iterator = _make_header_iterator(
headers={"apim-request-id": "azure-correlation-1"},
config=_headers_config(),
logging_obj=logging_obj,
)
async for _ in iterator:
pass
assert len(logged) == 1
iterator._completed_response_logged = False
logged.clear()
with patch.object(type(iterator.completed_response), "model_dump", side_effect=ValueError("cannot serialize")):
iterator._log_completed_response(is_async=True)
assert len(logged) == 1
assert logged[0] is not iterator.completed_response
assert logged[0].response is not iterator.completed_response.response
assert logged[0].response._hidden_params["headers"]["apim-request-id"] == "azure-correlation-1"
assert iterator.completed_response.response._hidden_params == {}
def _unvalidated_completed_config() -> Mock:
"""Config whose completed event carries a Perplexity-style response that fails validation
(``truncation: ""``) and already holds the stamped ``ResponseAPIUsage``."""
mock_config = Mock(spec=BaseResponsesAPIConfig)
def _transform(model, parsed_chunk, logging_obj):
response = _unvalidated_response_with_dict_usage(
ResponseAPIUsage(input_tokens=29, output_tokens=373, total_tokens=402, cost={"total_cost": 0.0001})
)
return ResponseCompletedEvent(type=ResponsesAPIStreamEvents.RESPONSE_COMPLETED, response=response)
mock_config.transform_streaming_response.side_effect = _transform
return mock_config
@pytest.mark.asyncio
async def test_streaming_logging_copy_keeps_client_usage_when_response_fails_validation():
"""LIT-7391: the logging copy cannot round-trip a response that fails validation, and logging
rewrites the assembled response's usage to chat shape in place, so the event handed to logging
must never be the one the caller receives."""
logging_obj = _logging_obj_stub()
logging_obj.stream = True
logged: list[object] = []
logging_obj.dispatch_success_handlers = _capture_dispatch(logged)
logging_obj._on_deferred_stream_complete = None
iterator = _make_header_iterator(headers={}, config=_unvalidated_completed_config(), logging_obj=logging_obj)
events = [event async for event in iterator]
assert len(logged) == 1
now = datetime.now()
LiteLLMLoggingObj._get_assembled_streaming_response(
logging_obj, logged[0], start_time=now, end_time=now, is_async=True, streaming_chunks=[]
)
assert logged[0].response.usage["prompt_tokens"] == 29
client_usage = events[-1].response.usage
assert isinstance(client_usage, ResponseAPIUsage)
assert client_usage.input_tokens == 29
assert client_usage.cost == pytest.approx(0.0001)