diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index b065d4dd91a..7203a176884 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -44,6 +44,7 @@ from litellm.constants import ( EMPTY_MAPPING, INTERNAL_CALLBACK_NAMES, KUBERNETES_POD_ROUTING_KEY, + LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL, PROVIDER_REQUEST_ID_HEADERS, REDACTED_BY_LITELLM, ) @@ -1531,15 +1532,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/unit/litellm_core_utils/test_litellm_logging.py b/tests/unit/litellm_core_utils/test_litellm_logging.py index 1d3bb2d0f34..041ab2a61b2 100644 --- a/tests/unit/litellm_core_utils/test_litellm_logging.py +++ b/tests/unit/litellm_core_utils/test_litellm_logging.py @@ -32,6 +32,7 @@ from litellm._service_logger import ServiceLogging from litellm.caching.caching import DualCache from litellm.constants import ( KUBERNETES_POD_ROUTING_KEY, + LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL, LOGGING_WORKER_MAX_TIME_PER_COROUTINE, REDACTED_BY_LITELLM, SENTRY_PII_DENYLIST, @@ -408,6 +409,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/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py b/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py index 336d2f3e7c2..34d6c165182 100644 --- a/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py +++ b/tests/unit/proxy/test_proxy_utils_model_creation_and_error_logging.py @@ -444,6 +444,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