diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index 7c176a36a7a..7e2c8d6e475 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -42,6 +42,7 @@ from litellm.constants import ( DEFAULT_MOCK_RESPONSE_COMPLETION_TOKEN_COUNT, DEFAULT_MOCK_RESPONSE_PROMPT_TOKEN_COUNT, EMPTY_MAPPING, + LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL, PROVIDER_REQUEST_ID_HEADERS, SENTRY_DENYLIST, SENTRY_PII_DENYLIST, @@ -1342,15 +1343,20 @@ class Logging(LiteLLMLoggingBaseClass): "LiteLLM.LoggingError: [Non-Blocking] Exception occurred while logging %s", e ) - self.model_call_details["api_call_start_time"] = datetime.datetime.now() - # Set-once first provider-handoff instant. api_call_start_time - # is overwritten on every retry, so it can't measure one-time - # preprocessing; pinning the first attempt excludes retry loops - # + backoff. Logging object only — must NOT go into - # litellm_params["metadata"] (caller request metadata, typed - # Dict[str, str], echoed downstream; a datetime breaks it). - if self.model_call_details.get("first_api_call_start_time") is None: - self.model_call_details["first_api_call_start_time"] = self.model_call_details["api_call_start_time"] + # A proxy-gate failure (auth, rate limit, client disconnect) fires pre_call for its callbacks + # without any provider handoff, so it must not stamp the handoff instants. + if LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL not in self.model_call_details: + self.model_call_details["api_call_start_time"] = datetime.datetime.now() + # Set-once first provider-handoff instant. api_call_start_time + # is overwritten on every retry, so it can't measure one-time + # preprocessing; pinning the first attempt excludes retry loops + # + backoff. Logging object only — must NOT go into + # litellm_params["metadata"] (caller request metadata, typed + # Dict[str, str], echoed downstream; a datetime breaks it). + if self.model_call_details.get("first_api_call_start_time") is None: + self.model_call_details["first_api_call_start_time"] = self.model_call_details[ + "api_call_start_time" + ] # Input Integration Logging -> If you want to log the fact that an attempt to call the model was made callbacks: Final = litellm.input_callback + (self.dynamic_input_callbacks or []) for callback in callbacks: diff --git a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py index fa4884ca47e..455bc2dd8c0 100644 --- a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py +++ b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py @@ -16,7 +16,7 @@ from openai._legacy_response import HttpxBinaryResponseContent import litellm from litellm._logging import session_id_var, trace_id_var -from litellm.constants import SENTRY_DENYLIST, SENTRY_PII_DENYLIST +from litellm.constants import LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL, SENTRY_DENYLIST, SENTRY_PII_DENYLIST from litellm.cost_calculator import ocr_batch_cost from litellm.integrations.custom_logger import CustomLogger from litellm.litellm_core_utils.litellm_logging import Logging as LitellmLogging @@ -73,6 +73,20 @@ def test_get_masked_api_base(logging_obj): assert type(masked_api_base) == str +@pytest.mark.parametrize("no_upstream_call", [False, True]) +def test_pre_call_stamps_the_provider_handoff_only_when_a_provider_call_is_made(logging_obj, no_upstream_call): + """The proxy fires pre_call for a failure it raised itself (auth, rate limit, client disconnect) + so callbacks see it; that call never reached a provider, so neither handoff instant may be set.""" + logging_obj.update_environment_variables(litellm_params={}, optional_params={}) + if no_upstream_call: + logging_obj.model_call_details[LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL] = True + + logging_obj.pre_call(input="", api_key="") + + assert ("api_call_start_time" in logging_obj.model_call_details) is not no_upstream_call + assert (logging_obj.model_call_details.get("first_api_call_start_time") is not None) is not no_upstream_call + + def test_pre_call_tolerates_missing_api_base(logging_obj): """Presigned batch retrieves (Mistral, Bedrock) build their own URL and pass api_base=None to pre_call; masking must not raise or the request's pre-call logging is silently lost.""" diff --git a/tests/test_litellm/proxy/test_proxy_utils.py b/tests/test_litellm/proxy/test_proxy_utils.py index 6b74a84c40f..d21ff23be3f 100644 --- a/tests/test_litellm/proxy/test_proxy_utils.py +++ b/tests/test_litellm/proxy/test_proxy_utils.py @@ -442,6 +442,47 @@ class TestPostCallFailureHookLiftsFirstApiCallStartTime: assert "litellm_logging_obj" not in request_data +class TestPostCallFailureHookDoesNotInventAProviderHandoff: + """A failure the proxy raised before any provider call (here an auth error) is logged through + _handle_logging_proxy_only_error, which fires pre_call for the callbacks. That must not stamp a + handoff instant onto the request, or every downstream reader (preprocessing latency, the + dispatched check behind the failure-row estimate) sees a provider call that never happened.""" + + @pytest.mark.asyncio + async def test_proxy_only_failure_lifts_no_first_api_call_start_time(self): + from datetime import datetime + from unittest.mock import AsyncMock, patch + + from litellm.litellm_core_utils.litellm_logging import Logging + from litellm.proxy._types import ProxyErrorTypes, UserAPIKeyAuth + + logging_obj = Logging( + model="gpt-4.1", + messages=[{"role": "user", "content": "hi"}], + stream=False, + call_type="acompletion", + start_time=datetime.now(), + litellm_call_id="pre-handoff-auth-failure", + function_id="pre-handoff", + ) + request_data: Final[dict[str, object]] = {"litellm_logging_obj": logging_obj, "model": "gpt-4.1", "metadata": {}} + proxy_logging_obj = ProxyLogging(user_api_key_cache=DualCache()) + proxy_logging_obj.alert_types = [] + with ( + patch.object(proxy_logging_obj, "update_request_status", new=AsyncMock()), + patch.object(proxy_logging_obj, "_dispatch_proxy_only_failure_handlers", new=AsyncMock()), + ): + await proxy_logging_obj.post_call_failure_hook( + request_data=request_data, + original_exception=Exception("Authentication Error, invalid key"), + user_api_key_dict=UserAPIKeyAuth(request_route="/v1/chat/completions"), + error_type=ProxyErrorTypes.auth_error, + ) + + assert request_data.get("first_api_call_start_time") is None + assert "api_call_start_time" not in logging_obj.model_call_details + + class TestPostCallFailureHookLiftsRecoveredPartialSpend: """A stream that broke mid-flight still billed the provider for the chunks already delivered. The streaming handler stashes that recovered usage and