From a44bb47563cdb6560aacb296a5de250271ec5bda Mon Sep 17 00:00:00 2001 From: Yassin Kortam Date: Sat, 22 Aug 2026 14:25:55 -0700 Subject: [PATCH] fix(prometheus): fold auth/pre-call time into litellm_request_total_latency_metric (#37958) litellm_request_total_latency_metric's start_time is set inside common_processing_pre_call_logic, which only runs after user_api_key_auth has already succeeded, so the metric silently excluded authentication and pre-call setup time despite being documented as total request latency. The sibling litellm_request_queue_time_seconds metric had the same problem: its arrival_time was captured after auth too, despite its own comment claiming to track when the request arrived at the proxy. request.state.litellm_received_at is now stamped unconditionally at the very first line of user_api_key_auth (previously only when OTEL was configured), giving a timestamp that precedes all auth work. Both metrics now derive from it: queue_time_seconds genuinely spans arrival through the start of pre-call processing, and the total-latency metric adds that queue time on top of its existing start/end window so it becomes true end-to-end latency. queue_time_seconds ends exactly at start_time rather than a separately captured timestamp, so its window and the total-latency window share a boundary instead of overlapping and double-counting a few lines of setup work on every request. --- litellm/integrations/prometheus.py | 27 +++- litellm/proxy/auth/user_api_key_auth.py | 27 +++- litellm/proxy/common_request_processing.py | 11 +- litellm/proxy/litellm_pre_call_utils.py | 16 ++- ...test_prometheus_queue_guardrail_metrics.py | 131 ++++++++++++++++++ .../proxy/auth/test_user_api_key_auth.py | 41 ++++++ .../proxy/test_common_request_processing.py | 20 ++- .../proxy/test_litellm_pre_call_utils.py | 73 +++++++++- 8 files changed, 321 insertions(+), 25 deletions(-) diff --git a/litellm/integrations/prometheus.py b/litellm/integrations/prometheus.py index 76066f4a305..f9195db1d67 100644 --- a/litellm/integrations/prometheus.py +++ b/litellm/integrations/prometheus.py @@ -215,7 +215,9 @@ class PrometheusLogger(CustomLogger): # request latency metrics self.litellm_request_total_latency_metric = self._histogram_factory( "litellm_request_total_latency_metric", - "Total latency (seconds) for a request to LiteLLM", + "End-to-end latency (seconds) for a request to LiteLLM Proxy Server, from the moment " + "the request reached the proxy through the end of processing -- includes " + "authentication, pre-call hooks, the LLM API call, and post-call processing", labelnames=self.get_labels_for_metric("litellm_request_total_latency_metric"), buckets=self.latency_buckets, ) @@ -458,7 +460,8 @@ class PrometheusLogger(CustomLogger): # Request queue time metric self.litellm_request_queue_time_metric = self._histogram_factory( "litellm_request_queue_time_seconds", - "Time spent in request queue before processing starts (seconds)", + "Time (seconds) from request arrival at the proxy to the start of pre-call " + "processing -- includes authentication and any ASGI-level queueing", labelnames=self.get_labels_for_metric("litellm_request_queue_time_seconds"), buckets=self.latency_buckets, ) @@ -2078,27 +2081,37 @@ class PrometheusLogger(CustomLogger): _labels, ) - # total request latency + # request queue time (time from arrival to processing start) -- read first so + # it can be folded into the total-latency metric below. start_time/end_time + # only span from after auth completes, so without this the "total" latency + # metric silently excludes auth and pre-call hook time. + _litellm_params: Final = kwargs.get("litellm_params", {}) or {} + queue_time_seconds: Final = (_litellm_params.get("metadata") or {}).get("queue_time_seconds") + + # total request latency: true end-to-end, from request arrival (queue_time_seconds, + # when available) through the end of processing. total_time_seconds: Final = self._safe_duration_seconds( start_time=start_time, end_time=end_time, ) if total_time_seconds is not None: + _observed_total_time_seconds: Final = ( + total_time_seconds + queue_time_seconds + if queue_time_seconds is not None and queue_time_seconds >= 0 + else total_time_seconds + ) _labels = prometheus_label_factory( supported_enum_labels=self.get_labels_for_metric(metric_name="litellm_request_total_latency_metric"), enum_values=enum_values, label_context=label_context, ) - self.litellm_request_total_latency_metric.labels(**_labels).observe(total_time_seconds) + self.litellm_request_total_latency_metric.labels(**_labels).observe(_observed_total_time_seconds) self._track_end_user_metric_series( self.litellm_request_total_latency_metric, "litellm_request_total_latency_metric", _labels, ) - # request queue time (time from arrival to processing start) - _litellm_params: Final = kwargs.get("litellm_params", {}) or {} - queue_time_seconds: Final = (_litellm_params.get("metadata") or {}).get("queue_time_seconds") if queue_time_seconds is not None and queue_time_seconds >= 0: _labels = prometheus_label_factory( supported_enum_labels=self.get_labels_for_metric(metric_name="litellm_request_queue_time_seconds"), diff --git a/litellm/proxy/auth/user_api_key_auth.py b/litellm/proxy/auth/user_api_key_auth.py index 84e60eb0dd8..658d176f6a7 100644 --- a/litellm/proxy/auth/user_api_key_auth.py +++ b/litellm/proxy/auth/user_api_key_auth.py @@ -1069,6 +1069,26 @@ async def _resolve_jwt_to_virtual_key( return None +def _ensure_litellm_received_at_on_request_state(request: Request) -> datetime: + """Idempotently stamp ``request.state.litellm_received_at`` with the moment + litellm's own code started handling this request -- the first line of + ``user_api_key_auth``, before any auth/pre-call work runs. This is the + basis for the request-latency Prometheus metrics (see + ``litellm/integrations/prometheus.py``), and unlike the OTEL SERVER span + below, it is set unconditionally so those metrics don't depend on OTEL + being configured. + """ + existing_received_at: Final[datetime | None] = getattr(request.state, "litellm_received_at", None) + if existing_received_at is not None: + return existing_received_at + received_at: Final = datetime.now(timezone.utc) + try: + request.state.litellm_received_at = received_at + except Exception: + pass + return received_at + + def _ensure_parent_otel_span_on_request_state(request: Request) -> None: """Idempotently create the OTEL SERVER span and stash it on ``request.state.parent_otel_span``. Safe to call multiple times. @@ -1079,15 +1099,12 @@ def _ensure_parent_otel_span_on_request_state(request: Request) -> None: """ from litellm.proxy.proxy_server import open_telemetry_logger + start_time: Final = _ensure_litellm_received_at_on_request_state(request) + if open_telemetry_logger is None: return if getattr(request.state, "parent_otel_span", None) is not None: return - start_time: Final = datetime.now(timezone.utc) - try: - request.state.litellm_received_at = start_time - except Exception: - pass parent_otel_span: Final = open_telemetry_logger.create_litellm_proxy_request_started_span( start_time=start_time, headers=_safe_get_request_headers(request), diff --git a/litellm/proxy/common_request_processing.py b/litellm/proxy/common_request_processing.py index 5f205df487d..dbbf9cb673e 100644 --- a/litellm/proxy/common_request_processing.py +++ b/litellm/proxy/common_request_processing.py @@ -3,7 +3,6 @@ import contextlib import json import logging import math -import time import traceback from collections.abc import AsyncGenerator, Awaitable, Callable, Mapping from datetime import datetime @@ -1726,13 +1725,17 @@ class ProxyBaseLLMRequestProcessing: ) # Calculate request queue time after add_litellm_data_to_request - # which sets arrival_time in proxy_server_request + # which sets arrival_time in proxy_server_request. Ends at start_time + # (not a freshly captured time.time() here) so this window is exactly + # [arrival_time, start_time], with zero overlap with the + # litellm_request_total_latency_metric window of [start_time, end_time] -- + # otherwise the few lines of add_litellm_data_to_request's own work would + # be double-counted across both metrics. proxy_server_request: Final = self.data.get("proxy_server_request", {}) arrival_time: Final = proxy_server_request.get("arrival_time") queue_time_seconds = None if arrival_time is not None: - processing_start_time: Final = time.time() - queue_time_seconds = processing_start_time - arrival_time + queue_time_seconds = start_time.timestamp() - arrival_time # Store queue time in metadata after add_litellm_data_to_request to ensure it's preserved if queue_time_seconds is not None: diff --git a/litellm/proxy/litellm_pre_call_utils.py b/litellm/proxy/litellm_pre_call_utils.py index 4525adb82f3..4794da05a3e 100644 --- a/litellm/proxy/litellm_pre_call_utils.py +++ b/litellm/proxy/litellm_pre_call_utils.py @@ -1744,11 +1744,17 @@ async def add_litellm_data_to_request( # Init - Proxy Server Request # we do this as soon as entering so we track the original request ########################################################## - # Track arrival time for queue time metric. The body snapshot is filled - # in after the admin-injection strip below so the audit / spend-tracking - # consumers of proxy_server_request["body"] see the cleaned metadata - # rather than attacker-forged user_api_key_* fields. - arrival_time: Final = time.time() + # Track arrival time for queue time metric. Prefer the timestamp stamped at + # the top of user_api_key_auth (request.state.litellm_received_at): by the + # time this function runs, auth has already completed, so time.time() here + # would silently exclude the entire auth phase from the queue-time window. + # Falls back to time.time() for callers that never went through + # user_api_key_auth. The body snapshot is filled in after the + # admin-injection strip below so the audit / spend-tracking consumers of + # proxy_server_request["body"] see the cleaned metadata rather than + # attacker-forged user_api_key_* fields. + _litellm_received_at: Final = getattr(request.state, "litellm_received_at", None) + arrival_time: Final = _litellm_received_at.timestamp() if _litellm_received_at is not None else time.time() data["proxy_server_request"] = { "url": str(request.url), "method": request.method, diff --git a/tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py b/tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py index 85be9e32121..f04e8d0d2c7 100644 --- a/tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py +++ b/tests/test_litellm/integrations/test_prometheus_queue_guardrail_metrics.py @@ -229,6 +229,137 @@ class TestPrometheusQueueTimeMetric: ), "Queue time metric should not be recorded for negative values" +class TestPrometheusTotalLatencyMetric: + """litellm_request_total_latency_metric must be true end-to-end latency: start_time + (set after auth already completed, see LIT-6012) plus queue_time_seconds (the + auth + pre-call setup window queue_time_seconds itself covers), not start_time alone.""" + + @staticmethod + def _enum_values() -> UserAPIKeyLabelValues: + return UserAPIKeyLabelValues( + end_user=None, + hashed_api_key="test-key", + api_key_alias="test-alias", + requested_model="gpt-3.5-turbo", + model_group="gpt-3.5-turbo", + team=None, + team_alias=None, + user=None, + user_email=None, + status_code="200", + model="gpt-3.5-turbo", + litellm_model_name="gpt-3.5-turbo", + tags=[], + model_id="gpt-3.5-turbo", + api_base="https://api.openai.com", + api_provider="openai", + exception_status=None, + exception_class=None, + custom_metadata_labels={}, + route=None, + ) + + def test_total_latency_includes_queue_time_when_present(self): + """The observed total-latency value must be (end_time - start_time) + queue_time_seconds, + so auth/pre-call time (queue_time_seconds) is not silently excluded from "total" latency.""" + prometheus_logger = PrometheusLogger() + + mock_metric = MagicMock() + mock_labeled_metric = MagicMock() + mock_metric.labels.return_value = mock_labeled_metric + prometheus_logger.litellm_request_total_latency_metric = mock_metric + + start_time = datetime(2024, 1, 1, 0, 0, 0) + end_time = datetime(2024, 1, 1, 0, 0, 2) # 2.0s of LLM-call/post-call time + queue_time_seconds = 0.5 # auth + pre-call setup time + + kwargs = { + "litellm_params": {"metadata": {"queue_time_seconds": queue_time_seconds}}, + "model": "gpt-3.5-turbo", + "start_time": start_time, + "end_time": end_time, + } + + prometheus_logger._set_latency_metrics( + kwargs=kwargs, + model="gpt-3.5-turbo", + user_api_key="test-key", + user_api_key_alias="test-alias", + user_api_team=None, + user_api_team_alias=None, + enum_values=self._enum_values(), + ) + + observed_value = mock_labeled_metric.observe.call_args_list[0][0][0] + assert observed_value == pytest.approx(2.5) + + def test_total_latency_falls_back_to_start_end_delta_without_queue_time(self): + """Without queue_time_seconds (e.g. a non-proxy caller), the metric must still + observe the plain end_time - start_time delta rather than erroring or dropping it.""" + prometheus_logger = PrometheusLogger() + + mock_metric = MagicMock() + mock_labeled_metric = MagicMock() + mock_metric.labels.return_value = mock_labeled_metric + prometheus_logger.litellm_request_total_latency_metric = mock_metric + + start_time = datetime(2024, 1, 1, 0, 0, 0) + end_time = datetime(2024, 1, 1, 0, 0, 2) + + kwargs = { + "litellm_params": {"metadata": {}}, + "model": "gpt-3.5-turbo", + "start_time": start_time, + "end_time": end_time, + } + + prometheus_logger._set_latency_metrics( + kwargs=kwargs, + model="gpt-3.5-turbo", + user_api_key="test-key", + user_api_key_alias="test-alias", + user_api_team=None, + user_api_team_alias=None, + enum_values=self._enum_values(), + ) + + observed_value = mock_labeled_metric.observe.call_args_list[0][0][0] + assert observed_value == pytest.approx(2.0) + + def test_total_latency_ignores_negative_queue_time(self): + """A negative queue_time_seconds (clock skew / bad data) must not be added in -- + matches the existing >= 0 guard on the standalone queue-time metric.""" + prometheus_logger = PrometheusLogger() + + mock_metric = MagicMock() + mock_labeled_metric = MagicMock() + mock_metric.labels.return_value = mock_labeled_metric + prometheus_logger.litellm_request_total_latency_metric = mock_metric + + start_time = datetime(2024, 1, 1, 0, 0, 0) + end_time = datetime(2024, 1, 1, 0, 0, 2) + + kwargs = { + "litellm_params": {"metadata": {"queue_time_seconds": -0.1}}, + "model": "gpt-3.5-turbo", + "start_time": start_time, + "end_time": end_time, + } + + prometheus_logger._set_latency_metrics( + kwargs=kwargs, + model="gpt-3.5-turbo", + user_api_key="test-key", + user_api_key_alias="test-alias", + user_api_team=None, + user_api_team_alias=None, + enum_values=self._enum_values(), + ) + + observed_value = mock_labeled_metric.observe.call_args_list[0][0][0] + assert observed_value == pytest.approx(2.0) + + class TestPrometheusGuardrailMetrics: """Test guardrail metrics recording""" diff --git a/tests/test_litellm/proxy/auth/test_user_api_key_auth.py b/tests/test_litellm/proxy/auth/test_user_api_key_auth.py index 470a01cfaa3..6a117985820 100644 --- a/tests/test_litellm/proxy/auth/test_user_api_key_auth.py +++ b/tests/test_litellm/proxy/auth/test_user_api_key_auth.py @@ -29,6 +29,8 @@ from litellm.proxy.auth.auth_checks import get_key_object, _cache_key_object from litellm.proxy.auth.route_checks import RouteChecks from litellm.proxy.auth.user_api_key_auth import ( _check_key_model_budget_with_fallback, + _ensure_litellm_received_at_on_request_state, + _ensure_parent_otel_span_on_request_state, _PendingAutoRegister, _matches_routing_override, _reserve_budget_after_common_checks, @@ -6694,3 +6696,42 @@ async def test_unlicensed_jwt_auth_is_forbidden_not_unauthorized(): assert error.code == "403" assert "enterprise" in error.message.lower() + + +class TestLitellmReceivedAtStamping: + """request.state.litellm_received_at must be stamped unconditionally at the + top of auth (LIT-6012), so request-latency Prometheus metrics don't depend + on OTEL being configured to see a true request-arrival timestamp.""" + + def test_stamped_even_when_otel_is_not_configured(self, monkeypatch): + monkeypatch.setattr( + "litellm.proxy.proxy_server.open_telemetry_logger", None + ) + request = MagicMock() + request.state = SimpleNamespace() + + _ensure_parent_otel_span_on_request_state(request) + + assert isinstance(request.state.litellm_received_at, datetime) + + def test_helper_is_idempotent(self): + request = MagicMock() + request.state = SimpleNamespace() + + first = _ensure_litellm_received_at_on_request_state(request) + second = _ensure_litellm_received_at_on_request_state(request) + + assert first == second + assert request.state.litellm_received_at == first + + def test_does_not_overwrite_an_earlier_stamp(self): + """Body-parse failures must not shorten the measured window: a value + already on request.state (stamped earlier) must win.""" + request = MagicMock() + earlier = datetime(2020, 1, 1) + request.state = SimpleNamespace(litellm_received_at=earlier) + + result = _ensure_litellm_received_at_on_request_state(request) + + assert result == earlier + assert request.state.litellm_received_at == earlier diff --git a/tests/test_litellm/proxy/test_common_request_processing.py b/tests/test_litellm/proxy/test_common_request_processing.py index f9ba91a246e..58714a5e319 100644 --- a/tests/test_litellm/proxy/test_common_request_processing.py +++ b/tests/test_litellm/proxy/test_common_request_processing.py @@ -1392,11 +1392,25 @@ class TestProxyBaseLLMRequestProcessing: route_type=route_type, ) - # Verify queue_time_seconds is set and non-negative + # Verify queue_time_seconds is set and non-negative. Ends at start_time + # (captured before this mock runs, so it can precede the mock's own + # time.time() by a handful of microseconds) rather than a freshly + # captured time.time(), so a tiny tolerance below 0.5 is expected and + # correct -- see LIT-6012. metadata = returned_data.get("metadata", {}) assert "queue_time_seconds" in metadata, "queue_time_seconds should be set in metadata" - assert metadata["queue_time_seconds"] >= 0.5, ( - f"queue_time_seconds should be at least 0.5, got {metadata['queue_time_seconds']}" + assert metadata["queue_time_seconds"] >= 0.49, ( + f"queue_time_seconds should be at least ~0.5, got {metadata['queue_time_seconds']}" + ) + + # queue_time_seconds must end exactly where logging_obj.start_time begins + # (the same start_time litellm_request_total_latency_metric's window + # starts from) so the two windows share a boundary, not an overlap. + # A mutant that reintroduces a separately-captured processing_start_time + # would make this assertion fail. + arrival_time = returned_data["proxy_server_request"]["arrival_time"] + assert arrival_time + metadata["queue_time_seconds"] == pytest.approx( + logging_obj.start_time.timestamp(), abs=1e-6 ) diff --git a/tests/test_litellm/proxy/test_litellm_pre_call_utils.py b/tests/test_litellm/proxy/test_litellm_pre_call_utils.py index 501b03eae0f..81a97a70efa 100644 --- a/tests/test_litellm/proxy/test_litellm_pre_call_utils.py +++ b/tests/test_litellm/proxy/test_litellm_pre_call_utils.py @@ -2,6 +2,9 @@ import asyncio import copy import json import os +import time +from datetime import datetime, timezone +from types import SimpleNamespace from unittest.mock import AsyncMock, MagicMock, patch import pytest @@ -268,6 +271,75 @@ async def test_stamped_auth_object_reflects_header_derived_identity(): assert stamped.end_user_id == "end-user-from-header" +@pytest.mark.asyncio +async def test_arrival_time_prefers_litellm_received_at_over_time_time(): + """LIT-6012: by the time this function runs, auth has already completed, so + time.time() here would silently exclude the whole auth phase from the + queue-time window. request.state.litellm_received_at (stamped at the top of + user_api_key_auth, before auth work) must win when present.""" + from litellm.proxy.litellm_pre_call_utils import add_litellm_data_to_request + + request_mock = MagicMock(spec=Request) + request_mock.url = MagicMock() + request_mock.url.path = "/v1/chat/completions" + request_mock.url.__str__.return_value = "http://localhost/v1/chat/completions" + request_mock.method = "POST" + request_mock.query_params = {} + request_mock.headers = {"Content-Type": "application/json"} + request_mock.client = MagicMock() + request_mock.client.host = "127.0.0.1" + received_at = datetime(2024, 1, 1, tzinfo=timezone.utc) + request_mock.state = SimpleNamespace(litellm_received_at=received_at) + + user_api_key_dict = UserAPIKeyAuth(api_key="hashed-key", metadata={}, team_metadata={}) + + updated_data = await add_litellm_data_to_request( + data={"model": "gpt-3.5-turbo"}, + request=request_mock, + user_api_key_dict=user_api_key_dict, + proxy_config=MagicMock(), + general_settings={}, + version="test-version", + ) + + assert updated_data["proxy_server_request"]["arrival_time"] == received_at.timestamp() + + +@pytest.mark.asyncio +async def test_arrival_time_falls_back_to_time_time_without_litellm_received_at(): + """Callers that never went through user_api_key_auth (no stamp on request.state) + must still get a usable arrival_time instead of erroring.""" + from litellm.proxy.litellm_pre_call_utils import add_litellm_data_to_request + + request_mock = MagicMock(spec=Request) + request_mock.url = MagicMock() + request_mock.url.path = "/v1/chat/completions" + request_mock.url.__str__.return_value = "http://localhost/v1/chat/completions" + request_mock.method = "POST" + request_mock.query_params = {} + request_mock.headers = {"Content-Type": "application/json"} + request_mock.client = MagicMock() + request_mock.client.host = "127.0.0.1" + request_mock.state = SimpleNamespace() # no litellm_received_at attribute + + user_api_key_dict = UserAPIKeyAuth(api_key="hashed-key", metadata={}, team_metadata={}) + + before = time.time() + updated_data = await add_litellm_data_to_request( + data={"model": "gpt-3.5-turbo"}, + request=request_mock, + user_api_key_dict=user_api_key_dict, + proxy_config=MagicMock(), + general_settings={}, + version="test-version", + ) + after = time.time() + + arrival_time = updated_data["proxy_server_request"]["arrival_time"] + assert isinstance(arrival_time, float) + assert before <= arrival_time <= after + + @pytest.mark.asyncio async def test_add_litellm_data_to_request_strips_admin_injection_slots(): """User-supplied user_api_key_metadata / user_api_key_team_metadata / @@ -2786,7 +2858,6 @@ def test_add_headers_to_llm_call_by_model_group_existing_headers_in_data(): litellm.model_group_settings = original_model_group_settings -import time from typing import Optional from fastapi.responses import Response