From 0300333753ce683d342f88a8e7520f13eddce374 Mon Sep 17 00:00:00 2001 From: ryan-crabbe-berri Date: Sat, 16 May 2026 13:45:08 -0700 Subject: [PATCH] feat(otel): OTel-standard attributes on the proxy SERVER span (status code, route/path, preprocessing latency) (#28040) * feat(otel): expose http.response.status_code on failure spans Set the OTel-standard http.response.status_code (integer) on failure spans alongside the existing OpenInference error.code (kept for back-compat). error.type is already emitted via ERROR_TYPE. Crucially, also record structured error attributes on the proxy SERVER span ('Received Proxy Server Request') from async_post_call_failure_hook - the only place the SERVER span is in hand. _handle_failure records on the litellm_request child span (the parent span is not propagated into its kwargs), so prior to this change the SERVER span that dashboards query carried only span status, never error.code/error.type. Reuses _record_exception_on_span + StandardLoggingPayloadSetup.get_error_information so values match the child span. Tests: recorder unit coverage + a hook-driven test asserting the SERVER span is stamped (the gap recorder-only tests missed). Full test_opentelemetry.py suite: 197 passed. * feat(otel): set http.route + url.path on the proxy SERVER span Add the OTel-standard http.route (low-cardinality route template, e.g. /v1/threads/{thread_id}/runs) and url.path (literal path) to the SERVER span ('Received Proxy Server Request') so dashboards can group traffic by endpoint instead of seeing every path param as a unique value. Same architectural gap as the status-code commit: the success/failure logging handlers write the litellm_request CHILD span, and _handle_success explicitly refuses to copy to the SERVER span. Verified with a console-exporter run that the SERVER span was bare on success. Unlike error info, route/path are known at request time, so set them directly on the freshly-created SERVER span in user_api_key_auth (one edit point, works for success and failure, no hook-ordering risk): - http.route from the matched FastAPI route (scope['route'].path), empirically confirmed populated at auth-dependency time. - url.path from the existing literal-path variable. New get_request_route_template helper + set_proxy_request_route_attributes (no-op on None span, so the Langfuse override stays safe). Tests: route-attribute setter + route-template helper edges. Full test_opentelemetry.py and test_auth_utils.py green. * feat(otel): set litellm.preprocessing.duration_ms on the proxy SERVER span Expose the total time LiteLLM spends before the upstream provider request begins (auth + parsing + pre-call hooks) as a single number on the SERVER span ('Received Proxy Server Request'). Window: proxy-receive -> FIRST provider handoff. Retry semantics: first attempt only (pure preprocessing, excludes retry loops + backoff). api_call_start_time is overwritten on every attempt, so a set-once first_api_call_start_time pins the first handoff. Same architectural gap as the prior two commits: the success/failure logging handlers write the litellm_request CHILD span, not the SERVER span. Set it instead from the post-call hooks on user_api_key_dict.parent_otel_span. Failure-path subtlety: request_data.pop('litellm_logging_obj') runs before the failure-hook loop, so the failure hook can't read the logging object. litellm_received_at is propagated via the existing request->metadata channel, and first_api_call_start_time is mirrored onto litellm_params.metadata, so both anchors survive into request_data and the OTel helper reads them uniformly for success and failure. Edits: user_api_key_auth (stash receive instant), litellm_pre_call_utils (propagate it), litellm_logging (set-once first handoff + metadata mirror), opentelemetry (constant + set_preprocessing_duration_attribute, called from both post-call hooks). Tests: duration helper (both container shapes, missing/negative/None edges) + set-once invariant (retry doesn't overwrite, metadata mirror). test_opentelemetry.py + test_auth_utils.py + test_litellm_logging.py: 447 passed. Verified live: SERVER span carries the attribute on success and failure, coexisting with the status-code and route attributes. * fix(otel): MyPy type-narrowing for status-code + preprocessing-duration No behavior change. MyPy (CI lint) flagged: - error_information["error_code"] is str|None: narrow via a None-checked local before int(). - _to_timestamp returns Optional[float]: resolve both anchors and return early if either is None instead of subtracting possibly-None floats. * fix(otel): stop polluting user request metadata with first_api_call_start_time The PR3 set-once preprocessing anchor was mirrored into litellm_params["metadata"] from core litellm_logging.py. That dict is the caller's request metadata, mutated in place and shared across every call path including pure SDK (litellm.acreate_batch). It got echoed into LiteLLMBatch(metadata=...), which the OpenAI batch schema types as Dict[str, str] -> pydantic ValidationError on a datetime value. - litellm_logging.py: set first_api_call_start_time only on model_call_details (success path reads it there directly). - proxy/utils.py: post_call_failure_hook lifts it off the logging object into request_data (internal top-level key, same convention as the other proxy-internal request_data keys) right before the existing litellm_logging_obj pop. Never touches user metadata. - opentelemetry.py: read the anchor from the container top level (model_call_details on success, request_data on failure). - Tests updated; add TestPostCallFailureHookLiftsFirstApiCallStartTime. Fixes the batches_testing regression introduced on this branch. * chore(otel): trim verbose comments to concise rationale Collapse multi-line why-blocks to one or two lines and drop process/plan references (PR-numbering, "the plan") from test comments. No behavior change. --- litellm/integrations/opentelemetry.py | 110 +++++++ litellm/litellm_core_utils/litellm_logging.py | 10 + litellm/proxy/auth/auth_utils.py | 19 ++ litellm/proxy/auth/user_api_key_auth.py | 13 + litellm/proxy/litellm_pre_call_utils.py | 6 + litellm/proxy/utils.py | 11 + .../integrations/test_opentelemetry.py | 280 ++++++++++++++++++ .../test_litellm_logging.py | 47 +++ .../proxy/auth/test_auth_utils.py | 42 +++ tests/test_litellm/proxy/test_proxy_utils.py | 57 ++++ 10 files changed, 595 insertions(+) diff --git a/litellm/integrations/opentelemetry.py b/litellm/integrations/opentelemetry.py index 41d1290761..29f9efba6d 100644 --- a/litellm/integrations/opentelemetry.py +++ b/litellm/integrations/opentelemetry.py @@ -59,6 +59,11 @@ LITELLM_TRACER_NAME = os.getenv("OTEL_TRACER_NAME", "litellm") LITELLM_METER_NAME = os.getenv("LITELLM_METER_NAME", "litellm") LITELLM_LOGGER_NAME = os.getenv("LITELLM_LOGGER_NAME", "litellm") LITELLM_PROXY_REQUEST_SPAN_NAME = "Received Proxy Server Request" +# OTel-standard names. status is also kept under error.code for back compat. +HTTP_RESPONSE_STATUS_CODE_ATTRIBUTE = "http.response.status_code" +HTTP_ROUTE_ATTRIBUTE = "http.route" +URL_PATH_ATTRIBUTE = "url.path" +PREPROCESSING_DURATION_MS_ATTRIBUTE = "litellm.preprocessing.duration_ms" # Remove the hardcoded LITELLM_RESOURCE dictionary - we'll create it properly later RAW_REQUEST_SPAN_NAME = "raw_gen_ai_request" LITELLM_REQUEST_SPAN_NAME = "litellm_request" @@ -667,6 +672,31 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): parent_otel_span = user_api_key_dict.parent_otel_span if parent_otel_span is not None: parent_otel_span.set_status(Status(StatusCode.ERROR)) + + # Stamp structured error attrs on the SERVER span itself; the + # failure path otherwise only sets its status (_handle_failure + # records on the litellm_request child span). Inline import: + # litellm_logging <-> integrations is circular. + from litellm.litellm_core_utils.litellm_logging import ( + StandardLoggingPayloadSetup, + ) + + error_information = StandardLoggingPayloadSetup.get_error_information( + original_exception=original_exception, + traceback_str=traceback_str, + ) + self._record_exception_on_span( + span=parent_otel_span, + kwargs={ + "exception": original_exception, + "standard_logging_object": {"error_information": error_information}, + }, + ) + + # Pre-request latency (request_data carries the propagated + # metadata on the failure path; omitted if it failed before handoff). + self.set_preprocessing_duration_attribute(parent_otel_span, request_data) + _span_name = "Failed Proxy Server Request" # Exception Logging Child Span @@ -703,6 +733,9 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): ctx, _ = self._get_span_context(kwargs, default_span=parent_span) + # Pre-request latency on the SERVER span (success path). + self.set_preprocessing_duration_attribute(parent_span, kwargs) + # 3. Guardrail span self._create_guardrail_span(kwargs=kwargs, context=ctx) @@ -1627,6 +1660,19 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): value=error_information["error_code"], ) + # Also expose under the OTel-standard name as an int + # (error_code is a str, may be non-numeric). + _error_code_val = error_information["error_code"] + if _error_code_val is not None: + try: + self.safe_set_attribute( + span=span, + key=HTTP_RESPONSE_STATUS_CODE_ATTRIBUTE, + value=int(_error_code_val), + ) + except (ValueError, TypeError): + pass + if error_information.get("error_class"): self.safe_set_attribute( span=span, @@ -2889,3 +2935,67 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): context=self.get_traceparent_from_header(headers=headers), kind=self.span_kind.SERVER, ) + + def set_proxy_request_route_attributes( + self, + span: Optional[Span], + *, + url_path: Optional[str] = None, + http_route: Optional[str] = None, + ) -> None: + """ + Set OTel-standard ``http.route`` / ``url.path`` on the proxy SERVER + span. Called from the auth path, the only point where both the + SERVER span and the request are in hand. No-op if span/value missing. + """ + if span is None: + return + if url_path: + self.safe_set_attribute(span=span, key=URL_PATH_ATTRIBUTE, value=url_path) + if http_route: + self.safe_set_attribute( + span=span, key=HTTP_ROUTE_ATTRIBUTE, value=http_route + ) + + def set_preprocessing_duration_attribute( + self, span: Optional[Span], container: Any + ) -> None: + """ + Set ``litellm.preprocessing.duration_ms`` (proxy-receive -> first + provider handoff) on the proxy SERVER span. ``litellm_received_at`` + rides request metadata; ``first_api_call_start_time`` is the + set-once first-handoff instant (retries/backoff excluded). Works + uniformly for the success (model_call_details) and failure + (request_data) containers. No-op if span/either anchor is missing. + """ + if span is None or not isinstance(container, dict): + return + received_at = None + # first_api_call_start_time is top-level (never in user metadata). + first_handoff = container.get("first_api_call_start_time") + _lp = container.get("litellm_params") + for _md in ( + (_lp or {}).get("metadata") if isinstance(_lp, dict) else None, + container.get("metadata"), + container.get("litellm_metadata"), + ): + if isinstance(_md, dict): + received_at = received_at or _md.get("litellm_received_at") + if received_at is None or first_handoff is None: + return + try: + start_ts = self._to_timestamp(received_at) + end_ts = self._to_timestamp(first_handoff) + except Exception: + return + if start_ts is None or end_ts is None: + return + duration_ms = (end_ts - start_ts) * 1000.0 + # Clock skew → omit rather than emit a negative latency. + if duration_ms < 0: + return + self.safe_set_attribute( + span=span, + key=PREPROCESSING_DURATION_MS_ATTRIBUTE, + value=duration_ms, + ) diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index c73d914e6c..876f1b167d 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -1050,6 +1050,16 @@ class Logging(LiteLLMLoggingBaseClass): ) 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 = litellm.input_callback + (self.dynamic_input_callbacks or []) for callback in callbacks: diff --git a/litellm/proxy/auth/auth_utils.py b/litellm/proxy/auth/auth_utils.py index ee86e92392..637a4a070c 100644 --- a/litellm/proxy/auth/auth_utils.py +++ b/litellm/proxy/auth/auth_utils.py @@ -522,6 +522,25 @@ def get_request_route(request: Request) -> str: return str(request.url.path) +def get_request_route_template(request: Request) -> Optional[str]: + """ + Return the low-cardinality route template, e.g. + ``/v1/threads/{thread_id}/runs`` (vs. the literal path from + ``get_request_route``). FastAPI sets ``scope["route"]`` before endpoint + dependencies run. Returns None if unavailable (unmatched path, Mount). + """ + try: + scope = request.scope + if not isinstance(scope, dict): + return None + route = scope.get("route") + template = getattr(route, "path", None) + return template if isinstance(template, str) and template else None + except Exception as e: + verbose_proxy_logger.debug(f"error on get_request_route_template: {str(e)}") + return None + + @lru_cache(maxsize=256) def normalize_request_route(route: str) -> str: """ diff --git a/litellm/proxy/auth/user_api_key_auth.py b/litellm/proxy/auth/user_api_key_auth.py index 03167c5a2d..30b5d36e14 100644 --- a/litellm/proxy/auth/user_api_key_auth.py +++ b/litellm/proxy/auth/user_api_key_auth.py @@ -51,6 +51,7 @@ from litellm.proxy.auth.auth_utils import ( get_end_user_id_from_request_body, get_model_from_request, get_request_route, + get_request_route_template, normalize_request_route, pre_db_read_auth_checks, route_in_additonal_public_routes, @@ -682,6 +683,12 @@ async def _user_api_key_auth_builder( # noqa: PLR0915 parent_otel_span: Optional[Span] = None start_time = datetime.now() + # Stash the proxy-receive instant for the pre-request latency calc — + # the OTel Span API exposes no start-time getter, so propagate it. + try: + request.state.litellm_received_at = start_time + except Exception: + pass route: str = get_request_route(request=request) valid_token: Optional[UserAPIKeyAuth] = None custom_auth_api_key: bool = False @@ -723,6 +730,12 @@ async def _user_api_key_auth_builder( # noqa: PLR0915 headers=_safe_get_request_headers(request), ) ) + # `route` is the literal path; template from the matched route. + open_telemetry_logger.set_proxy_request_route_attributes( + parent_otel_span, + url_path=route, + http_route=get_request_route_template(request), + ) ### USER-DEFINED AUTH FUNCTION ### if enterprise_custom_auth is not None: diff --git a/litellm/proxy/litellm_pre_call_utils.py b/litellm/proxy/litellm_pre_call_utils.py index 7cd099a729..8cb9a11ffe 100644 --- a/litellm/proxy/litellm_pre_call_utils.py +++ b/litellm/proxy/litellm_pre_call_utils.py @@ -1651,6 +1651,12 @@ async def add_litellm_data_to_request( # noqa: PLR0915 ) data[_metadata_variable_name]["headers"] = _headers data[_metadata_variable_name]["endpoint"] = str(request.url) + # Carry the proxy-receive instant via metadata (like `endpoint`) so the + # OTel layer can compute pre-request latency, including on the failure + # path after the logging object is popped. + data[_metadata_variable_name]["litellm_received_at"] = getattr( + request.state, "litellm_received_at", None + ) # OTEL Controls / Tracing # Add the OTEL Parent Trace before sending it LiteLLM diff --git a/litellm/proxy/utils.py b/litellm/proxy/utils.py index 871f084c58..32c887f17b 100644 --- a/litellm/proxy/utils.py +++ b/litellm/proxy/utils.py @@ -1984,6 +1984,17 @@ class ProxyLogging: original_exception=original_exception, ) + # Lift the first-handoff instant onto request_data (top-level + # internal key, not metadata) so failure-path callbacks can still + # compute preprocessing latency after the logging object is popped. + _logging_obj = request_data.get("litellm_logging_obj") + if _logging_obj is not None: + _first_handoff = getattr(_logging_obj, "model_call_details", {}).get( + "first_api_call_start_time" + ) + if _first_handoff is not None: + request_data["first_api_call_start_time"] = _first_handoff + # Remove before callbacks iterate — not serialisable request_data.pop("litellm_logging_obj", None) diff --git a/tests/test_litellm/integrations/test_opentelemetry.py b/tests/test_litellm/integrations/test_opentelemetry.py index 27356038cd..a98ad2c95a 100644 --- a/tests/test_litellm/integrations/test_opentelemetry.py +++ b/tests/test_litellm/integrations/test_opentelemetry.py @@ -1,3 +1,4 @@ +import asyncio import json import os import sys @@ -4625,3 +4626,282 @@ class TestOpenTelemetrySpanDedupe(unittest.TestCase): 2, f"Two distinct guardrail invocations expected, got {len(guardrail_spans)}", ) + + +class TestOpenTelemetryHttpStatusCodeAttribute(unittest.TestCase): + """PR 1: the failure recorder also exposes the HTTP status under the + OTel-standard ``http.response.status_code`` (as an int), while keeping the + legacy ``error.code`` for back-compat and leaving span status untouched. + """ + + def _record(self, error_information): + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = provider.get_tracer(__name__) + + otel = OpenTelemetry() + span = tracer.start_span("Received Proxy Server Request") + kwargs = { + "exception": ValueError("boom"), + "standard_logging_object": {"error_information": error_information}, + } + otel._record_exception_on_span(span=span, kwargs=kwargs) + span.end() + + finished = exporter.get_finished_spans() + assert len(finished) == 1 + return finished[0] + + def test_401_sets_int_status_code_and_error_type(self): + span = self._record({"error_code": "401", "error_class": "AuthenticationError"}) + assert span.attributes["http.response.status_code"] == 401 + assert isinstance(span.attributes["http.response.status_code"], int) + assert span.attributes["error.type"] == "AuthenticationError" + + def test_429_terminal(self): + span = self._record({"error_code": "429"}) + assert span.attributes["http.response.status_code"] == 429 + + def test_500_sets_status_code_and_records_exception_event(self): + span = self._record({"error_code": "500"}) + assert span.attributes["http.response.status_code"] == 500 + assert any(e.name == "exception" for e in span.events) + + def test_legacy_error_code_still_present_no_regression(self): + span = self._record({"error_code": "401"}) + assert span.attributes["error.code"] == "401" + + def test_non_numeric_error_code_omits_status_code(self): + span = self._record({"error_code": "ContextWindowExceeded"}) + assert "http.response.status_code" not in span.attributes + # legacy attribute still set so existing dashboards don't regress + assert span.attributes["error.code"] == "ContextWindowExceeded" + + def test_empty_error_code_omits_status_code(self): + span = self._record({"error_code": ""}) + assert "http.response.status_code" not in span.attributes + + def test_recorder_does_not_touch_span_status(self): + span = self._record({"error_code": "401"}) + assert span.status.status_code == trace.StatusCode.UNSET + + +class TestOpenTelemetryFailureHookStampsServerSpan(unittest.TestCase): + """Error attributes must land on the SERVER span dashboards query. + ``_handle_failure`` records on the litellm_request child span, so + ``async_post_call_failure_hook`` — which holds the SERVER span via + ``user_api_key_dict.parent_otel_span`` — is where it gets stamped. + """ + + def _run_hook(self, exception): + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = provider.get_tracer(__name__) + + otel = OpenTelemetry() + otel.tracer = tracer + server_span = tracer.start_span("Received Proxy Server Request") + + user_api_key_dict = MagicMock() + user_api_key_dict.parent_otel_span = server_span + + asyncio.run( + otel.async_post_call_failure_hook( + request_data={}, + original_exception=exception, + user_api_key_dict=user_api_key_dict, + traceback_str="trace", + ) + ) + + finished = {s.name: s for s in exporter.get_finished_spans()} + assert "Received Proxy Server Request" in finished + return finished["Received Proxy Server Request"] + + def test_server_span_gets_int_status_code_and_error_type(self): + class _Boom(Exception): + status_code = 500 + + span = self._run_hook(_Boom("upstream blew up")) + assert span.attributes["http.response.status_code"] == 500 + assert isinstance(span.attributes["http.response.status_code"], int) + assert span.attributes["error.type"] == "_Boom" + assert span.attributes["error.code"] == "500" # legacy, string + assert span.status.status_code == trace.StatusCode.ERROR + + def test_non_numeric_code_omits_status_code_no_crash(self): + class _Boom(Exception): + code = "ContextWindowExceeded" + + span = self._run_hook(_Boom("bad")) + assert "http.response.status_code" not in span.attributes + assert span.attributes["error.code"] == "ContextWindowExceeded" + + def test_no_parent_span_is_noop(self): + otel = OpenTelemetry() + otel.tracer = MagicMock() + user_api_key_dict = MagicMock() + user_api_key_dict.parent_otel_span = None + # Must not raise when there is no SERVER span (e.g. pre-auth 401). + asyncio.run( + otel.async_post_call_failure_hook( + request_data={}, + original_exception=ValueError("x"), + user_api_key_dict=user_api_key_dict, + traceback_str=None, + ) + ) + + +class TestOpenTelemetrySetProxyRequestRouteAttributes(unittest.TestCase): + """http.route (template) + url.path (literal) must land on the SERVER + span. The logging handlers write the litellm_request child span, so + this is set from the auth path on the freshly-created SERVER span. + """ + + def _set(self, **kwargs): + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = provider.get_tracer(__name__) + + otel = OpenTelemetry() + span = tracer.start_span("Received Proxy Server Request") + otel.set_proxy_request_route_attributes(span, **kwargs) + span.end() + return exporter.get_finished_spans()[0] + + def test_sets_named_template_and_literal(self): + span = self._set( + url_path="/v1/threads/abc123/runs", + http_route="/v1/threads/{thread_id}/runs", + ) + # Exact OTel-standard names — NOT metadata.* (naming regression guard). + assert span.attributes["url.path"] == "/v1/threads/abc123/runs" + assert span.attributes["http.route"] == "/v1/threads/{thread_id}/runs" + assert span.attributes["http.route"] != span.attributes["url.path"] + assert "metadata.http_route" not in span.attributes + + def test_flat_route_template_equals_literal(self): + span = self._set( + url_path="/v1/chat/completions", + http_route="/v1/chat/completions", + ) + assert span.attributes["http.route"] == "/v1/chat/completions" + assert span.attributes["url.path"] == "/v1/chat/completions" + + def test_missing_http_route_omits_only_that_attribute(self): + span = self._set(url_path="/v1/chat/completions", http_route=None) + assert span.attributes["url.path"] == "/v1/chat/completions" + assert "http.route" not in span.attributes + + def test_missing_both_sets_nothing(self): + span = self._set(url_path=None, http_route=None) + assert "url.path" not in span.attributes + assert "http.route" not in span.attributes + + def test_none_span_is_noop(self): + otel = OpenTelemetry() + # Mirrors the Langfuse-override path (create span returns None). + otel.set_proxy_request_route_attributes(None, url_path="/x", http_route="/x") + + +class TestOpenTelemetryPreprocessingDuration(unittest.TestCase): + """litellm.preprocessing.duration_ms (proxy-receive -> first provider + handoff) on the SERVER span. Read from container metadata so the + success (model_call_details) and failure (request_data) paths work + uniformly. Excludes retries via the set-once first_api_call_start_time. + """ + + def _span(self): + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + tracer = provider.get_tracer(__name__) + return tracer.start_span("Received Proxy Server Request"), exporter + + def _attr(self, span, exporter): + span.end() + return exporter.get_finished_spans()[0].attributes + + def test_success_shape_model_call_details(self): + # success path: first_api_call_start_time top-level, + # received-at under litellm_params.metadata + received = datetime(2026, 1, 1, 0, 0, 0) + handoff = datetime(2026, 1, 1, 0, 0, 0, 250000) # +250ms + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute( + span, + { + "first_api_call_start_time": handoff, + "litellm_params": {"metadata": {"litellm_received_at": received}}, + }, + ) + attrs = self._attr(span, exp) + self.assertAlmostEqual( + attrs["litellm.preprocessing.duration_ms"], 250.0, places=1 + ) + + def test_failure_shape_request_data(self): + # failure path: request_data with first_api_call_start_time lifted + # to the TOP LEVEL by the proxy (off the logging object, before it + # is popped) and received-at riding the metadata variable. The + # user metadata sub-dict is never used for the handoff anchor. + received = datetime(2026, 1, 1, 0, 0, 0) + handoff = datetime(2026, 1, 1, 0, 0, 0, 30000) # +30ms + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute( + span, + { + "first_api_call_start_time": handoff, + "metadata": {"litellm_received_at": received}, + }, + ) + attrs = self._attr(span, exp) + self.assertAlmostEqual( + attrs["litellm.preprocessing.duration_ms"], 30.0, places=1 + ) + + def test_missing_received_at_omits(self): + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute( + span, {"first_api_call_start_time": datetime(2026, 1, 1)} + ) + assert "litellm.preprocessing.duration_ms" not in self._attr(span, exp) + + def test_missing_handoff_omits(self): + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute( + span, {"metadata": {"litellm_received_at": datetime(2026, 1, 1)}} + ) + assert "litellm.preprocessing.duration_ms" not in self._attr(span, exp) + + def test_negative_duration_omitted(self): + # clock skew: handoff before receive -> omit, not a negative value + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute( + span, + { + "first_api_call_start_time": datetime(2026, 1, 1, 0, 0, 0), + "metadata": {"litellm_received_at": datetime(2026, 1, 1, 0, 0, 5)}, + }, + ) + assert "litellm.preprocessing.duration_ms" not in self._attr(span, exp) + + def test_none_span_is_noop(self): + OpenTelemetry().set_preprocessing_duration_attribute( + None, {"first_api_call_start_time": datetime(2026, 1, 1)} + ) + + def test_non_dict_container_is_noop(self): + otel = OpenTelemetry() + span, exp = self._span() + otel.set_preprocessing_duration_attribute(span, None) + assert "litellm.preprocessing.duration_ms" not in self._attr(span, exp) 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 e84baf5e13..c6961477a5 100644 --- a/tests/test_litellm/litellm_core_utils/test_litellm_logging.py +++ b/tests/test_litellm/litellm_core_utils/test_litellm_logging.py @@ -2685,3 +2685,50 @@ def test_success_handler_unified_helper_runs_for_typed_results(): ) mock_calc.assert_called_once() assert logging_obj.model_call_details["response_cost"] == expected_cost + + +class TestFirstApiCallStartTimeSetOnce: + """first_api_call_start_time pins the FIRST provider handoff so + preprocessing latency excludes retries/backoff (api_call_start_time is + overwritten on every attempt). It is set ONLY on the logging object's + model_call_details. It must never be written into + litellm_params["metadata"] — that is the caller's request metadata, + echoed back into provider request bodies, spend logs, and batch + objects (typed Dict[str, str]); a datetime there breaks them. The + proxy failure path lifts it off the logging object into request_data + separately (see proxy/utils.py), not via this dict. + """ + + def _logging_obj(self): + obj = LitellmLogging( + model="gpt-4", + messages=[{"role": "user", "content": "hi"}], + stream=False, + call_type="completion", + start_time=time.time(), + litellm_call_id="set-once-1", + function_id="f1", + ) + obj.model_call_details["litellm_params"] = {"metadata": {}} + return obj + + def test_set_once_survives_retry_and_never_touches_user_metadata(self): + obj = self._logging_obj() + user_meta = obj.model_call_details["litellm_params"]["metadata"] + + obj.pre_call(input="hi", api_key="sk-test") + first = obj.model_call_details["first_api_call_start_time"] + assert first == obj.model_call_details["api_call_start_time"] + # Set on the logging object only — user metadata untouched. + assert user_meta == {} + assert ( + "first_api_call_start_time" not in obj.model_call_details["litellm_params"] + ) + + time.sleep(0.002) # ensure a distinct retry timestamp + obj.pre_call(input="hi", api_key="sk-test") + + # retry advanced api_call_start_time but NOT first_api_call_start_time + assert obj.model_call_details["api_call_start_time"] > first + assert obj.model_call_details["first_api_call_start_time"] == first + assert user_meta == {} diff --git a/tests/test_litellm/proxy/auth/test_auth_utils.py b/tests/test_litellm/proxy/auth/test_auth_utils.py index 70e8812c99..08035fb717 100644 --- a/tests/test_litellm/proxy/auth/test_auth_utils.py +++ b/tests/test_litellm/proxy/auth/test_auth_utils.py @@ -19,6 +19,7 @@ from litellm.proxy.auth.auth_utils import ( get_model_from_request, get_project_model_rpm_limit, get_project_model_tpm_limit, + get_request_route_template, is_request_body_safe, ) @@ -1573,3 +1574,44 @@ class TestPricingInjectionBlocked: ) is True ) + + +class TestGetRequestRouteTemplate: + """get_request_route_template returns the low-cardinality FastAPI route + template (e.g. /v1/threads/{thread_id}/runs) for http.route, distinct + from the literal url.path. None when unavailable.""" + + def _request(self, scope): + req = MagicMock() + req.scope = scope + return req + + def test_returns_route_template(self): + route = MagicMock() + route.path = "/v1/threads/{thread_id}/runs" + req = self._request({"route": route, "path": "/v1/threads/abc123/runs"}) + # template, not the literal path — two thread IDs share this value + assert get_request_route_template(req) == "/v1/threads/{thread_id}/runs" + + def test_scope_not_dict_returns_none(self): + assert get_request_route_template(self._request("not-a-dict")) is None + + def test_no_route_in_scope_returns_none(self): + assert get_request_route_template(self._request({"path": "/x"})) is None + + def test_route_without_str_path_returns_none(self): + route = MagicMock() + route.path = 12345 # not a str + assert get_request_route_template(self._request({"route": route})) is None + + def test_route_with_empty_path_returns_none(self): + route = MagicMock() + route.path = "" + assert get_request_route_template(self._request({"route": route})) is None + + def test_exception_returns_none(self): + req = MagicMock() + type(req).scope = property( + lambda self: (_ for _ in ()).throw(RuntimeError("boom")) + ) + assert get_request_route_template(req) is None diff --git a/tests/test_litellm/proxy/test_proxy_utils.py b/tests/test_litellm/proxy/test_proxy_utils.py index 2605eadba7..7a2b20bd8f 100644 --- a/tests/test_litellm/proxy/test_proxy_utils.py +++ b/tests/test_litellm/proxy/test_proxy_utils.py @@ -264,3 +264,60 @@ def test_enrich_http_exception_callback_without_guardrail_name_noop(): exc = HTTPException(status_code=400, detail={"error": "x"}) _enrich_http_exception_with_guardrail_context(exc, StubCallback()) assert exc.detail == {"error": "x"} + + +class TestPostCallFailureHookLiftsFirstApiCallStartTime: + """post_call_failure_hook lifts first_api_call_start_time off the + logging object into request_data (an internal top-level key) before + the non-serialisable logging object is popped, so failure-path + callbacks (OTel preprocessing latency) can still read it. It must + never land in request_data["metadata"] (user request metadata, + echoed downstream and typed Dict[str, str] in batch objects). + """ + + async def _run(self, request_data): + from unittest.mock import AsyncMock, patch + + from litellm.proxy._types import UserAPIKeyAuth + + proxy_logging_obj = ProxyLogging(user_api_key_cache=DualCache()) + proxy_logging_obj.alert_types = [] # skip alerting branch + with patch.object(proxy_logging_obj, "update_request_status", new=AsyncMock()): + await proxy_logging_obj.post_call_failure_hook( + request_data=request_data, + original_exception=Exception("boom"), + user_api_key_dict=UserAPIKeyAuth(), + ) + + @pytest.mark.asyncio + async def test_lifts_to_top_level_and_pops_logging_obj(self): + handoff = real_datetime.datetime(2026, 1, 1, 0, 0, 0) + logging_obj = MagicMock() + logging_obj.model_call_details = {"first_api_call_start_time": handoff} + user_meta = {} + request_data = { + "litellm_logging_obj": logging_obj, + "metadata": user_meta, + } + await self._run(request_data) + + assert request_data["first_api_call_start_time"] == handoff + assert "litellm_logging_obj" not in request_data + # user metadata is never touched + assert user_meta == {} + assert "first_api_call_start_time" not in request_data["metadata"] + + @pytest.mark.asyncio + async def test_no_logging_obj_is_noop(self): + request_data = {"metadata": {}} + await self._run(request_data) + assert "first_api_call_start_time" not in request_data + + @pytest.mark.asyncio + async def test_logging_obj_without_anchor_is_noop(self): + logging_obj = MagicMock() + logging_obj.model_call_details = {} + request_data = {"litellm_logging_obj": logging_obj} + await self._run(request_data) + assert "first_api_call_start_time" not in request_data + assert "litellm_logging_obj" not in request_data