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.
This commit is contained in:
parent
62dca9e977
commit
0300333753
@ -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,
|
||||
)
|
||||
|
||||
@ -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:
|
||||
|
||||
@ -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:
|
||||
"""
|
||||
|
||||
@ -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:
|
||||
|
||||
@ -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
|
||||
|
||||
@ -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)
|
||||
|
||||
|
||||
@ -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)
|
||||
|
||||
@ -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 == {}
|
||||
|
||||
@ -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
|
||||
|
||||
@ -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
|
||||
|
||||
Loading…
Reference in New Issue
Block a user