From 08223e1ec3a7ff2356fcf2f5b3a39868f2eb37ca Mon Sep 17 00:00:00 2001 From: Yassin Kortam Date: Tue, 2 Jun 2026 18:25:15 -0700 Subject: [PATCH] fix: missing span for guardrail passthrough (#29552) --- litellm/_service_logger.py | 2 + litellm/integrations/custom_guardrail.py | 10 ++ litellm/integrations/opentelemetry.py | 4 + litellm/integrations/otel/logger.py | 80 ++++++------- litellm/integrations/otel/model/metadata.py | 20 ---- .../integrations/otel/test_otel_v2_logger.py | 108 ++++++++++++------ .../integrations/test_custom_guardrail.py | 59 ++++++++++ .../integrations/test_opentelemetry.py | 25 ++++ ...t_passthrough_guardrail_block_otel_span.py | 16 +-- tests/test_litellm/test_service_logger.py | 27 +++++ 10 files changed, 250 insertions(+), 101 deletions(-) diff --git a/litellm/_service_logger.py b/litellm/_service_logger.py index 5531c41879..b290b4340e 100644 --- a/litellm/_service_logger.py +++ b/litellm/_service_logger.py @@ -371,6 +371,8 @@ class ServiceLogging(CustomLogger): service=ServiceTypes.LITELLM, duration=_duration, call_type=kwargs.get("call_type", "unknown"), + start_time=start_time, + end_time=end_time, ) except Exception as e: raise e diff --git a/litellm/integrations/custom_guardrail.py b/litellm/integrations/custom_guardrail.py index 82a35f2eed..6d0d73e033 100644 --- a/litellm/integrations/custom_guardrail.py +++ b/litellm/integrations/custom_guardrail.py @@ -662,6 +662,16 @@ class CustomGuardrail(CustomLogger): request_data["metadata"] = {} _append_guardrail_info(request_data["metadata"]) + # Emit the otel guardrail span here, where every guardrail execution lands, + # rather than relying on a post-call hook that does not fire on every path + # (e.g. a pass-through request that passes its guardrails). + try: + from litellm.integrations.otel.logger import emit_guardrail_span + + emit_guardrail_span(slg) + except Exception: + pass + async def apply_guardrail( self, inputs: GenericGuardrailAPIInputs, diff --git a/litellm/integrations/opentelemetry.py b/litellm/integrations/opentelemetry.py index 8bc61d960e..ce5cfa2f52 100644 --- a/litellm/integrations/opentelemetry.py +++ b/litellm/integrations/opentelemetry.py @@ -2668,6 +2668,10 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger): ) def _to_ns(self, dt): + if dt is None: + return int(datetime.now().timestamp() * 1e9) + if isinstance(dt, (int, float)): + return int(dt * 1e9) return int(dt.timestamp() * 1e9) def _get_span_name(self, kwargs): diff --git a/litellm/integrations/otel/logger.py b/litellm/integrations/otel/logger.py index de5e7a7b8a..57738c356f 100644 --- a/litellm/integrations/otel/logger.py +++ b/litellm/integrations/otel/logger.py @@ -25,7 +25,6 @@ from litellm.integrations.otel.mappers import resolve_mappers from litellm.integrations.otel.model.metadata import ( LLMCallEvent, RequestIdentity, - guardrail_entries_from_request_data, model_from_request_data, ) from litellm.integrations.otel.model.payloads import ( @@ -468,46 +467,27 @@ class OpenTelemetryV2(CustomLogger): ) return data - async def async_post_call_success_hook( - self, - data: Mapping[str, Any], - user_api_key_dict: Any, - response: Any, - ) -> Any: - self._emit_guardrail_spans(data) - return response - - async def async_post_call_failure_hook( - self, - request_data: Mapping[str, Any], - original_exception: BaseException | None, - user_api_key_dict: Any, - traceback_str: str | None = None, - ) -> None: - self._emit_guardrail_spans(request_data) - - def _emit_guardrail_spans(self, request_data: Mapping[str, Any]) -> None: + def emit_guardrail_span(self, entry: "StandardLoggingGuardrailInformation") -> None: + # Emitted by the guardrail-recording code the moment a guardrail finishes, + # not from a post-call hook — that hook does not fire on every path (a + # pass-through request that passes its guardrails never reaches it), which + # left passing guardrails without a span. + # # A guardrail is a sibling of the LLM call under the request's root span, - # so parent it to the explicit anchor — not the active span, which on the - # failure path can be the live ``auth`` phase span (post-call failure hooks - # run from inside it on an auth rejection). Emit with the guardrail's actual - # execution window so a pre_call guardrail is placed before the LLM call - # rather than at post-call emission time. - guardrails = guardrail_entries_from_request_data(request_data) - if not guardrails: - return - parent_ctx = resolve_request_span_context() - for entry in guardrails: - data = GuardrailSpanData.from_logging_entry( - cast("StandardLoggingGuardrailInformation", entry) - ) - self._emitter.emit( - SpanRole.GUARDRAIL, - data, - parent_context=parent_ctx, - start_time_ns=to_ns(data.start_time), - end_time_ns=to_ns(data.end_time), - ) + # so parent it to the explicit anchor — never the active span, which during + # a pre_call guardrail can be the live ``auth`` phase span. Emit with the + # guardrail's actual execution window so a pre_call guardrail is placed + # before the LLM call rather than at emission time. One entry in, one span + # out — the module-level entry point routes each entry to this single + # registered logger so a guardrail is never emitted more than once. + data = GuardrailSpanData.from_logging_entry(entry) + self._emitter.emit( + SpanRole.GUARDRAIL, + data, + parent_context=resolve_request_span_context(), + start_time_ns=to_ns(data.start_time), + end_time_ns=to_ns(data.end_time), + ) def create_litellm_proxy_request_started_span( self, start_time: datetime, headers: Mapping[str, str] | None @@ -528,6 +508,26 @@ def _registered_v2_logger() -> "OpenTelemetryV2 | None": return logger if isinstance(logger, OpenTelemetryV2) else None +def emit_guardrail_span(entry: "StandardLoggingGuardrailInformation") -> None: + """Emit a guardrail span on the registered v2 OTel logger. + + Called by the guardrail-recording code the moment a guardrail finishes, so a + span is produced regardless of whether a post-call hook later runs (it does + not on the pass-through allow path). Routes through the single canonical + logger — the same one every other v2 entry point uses — so a guardrail + recorded once yields exactly one span; fanning out across every reachable + ``OpenTelemetryV2`` instance double-emits the same entry. Best-effort: span + emission must never break guardrail evaluation. + """ + logger = _registered_v2_logger() + if logger is None: + return + try: + logger.emit_guardrail_span(entry) + except Exception: + pass + + def seed_request_identity(user_api_key_dict: Any, model: Any = None) -> None: logger = _registered_v2_logger() if logger is not None: diff --git a/litellm/integrations/otel/model/metadata.py b/litellm/integrations/otel/model/metadata.py index 4663ed5976..4c9cecfef5 100644 --- a/litellm/integrations/otel/model/metadata.py +++ b/litellm/integrations/otel/model/metadata.py @@ -255,26 +255,6 @@ def model_from_request_data(data: object) -> str | None: return None -def guardrail_entries_from_request_data( - request_data: Mapping[str, Any], -) -> list[dict]: - """The guardrail-information dicts buried in ``metadata`` of a post-call dict. - - ``standard_logging_guardrail_information`` is stored as either a single dict - or a list of them; normalize to a list of dicts (dropping non-dict noise) so - the caller just iterates. Empty list when none are present. - """ - metadata = request_data.get("metadata") - if not isinstance(metadata, Mapping): - return [] - info = metadata.get("standard_logging_guardrail_information") - if isinstance(info, Mapping): - return [cast(dict, info)] - if isinstance(info, list): - return [entry for entry in info if isinstance(entry, dict)] - return [] - - def resolve_provider_model(payload: "StandardLoggingPayload") -> str | None: """The model litellm dispatched to the provider, from the payload. diff --git a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py b/tests/test_litellm/integrations/otel/test_otel_v2_logger.py index 971bb9340b..9947ce9ac9 100644 --- a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py +++ b/tests/test_litellm/integrations/otel/test_otel_v2_logger.py @@ -541,17 +541,10 @@ def test_guardrail_span_anchors_to_root_inside_active_phase_span(): SpanRole.PROXY_REQUEST, LITELLM_PROXY_REQUEST_SPAN_NAME ) set_request_root_span(server) - request_data = { - "metadata": { - "standard_logging_guardrail_information": { - "guardrail_name": "my_guard", - "guardrail_status": "success", - } - } - } + entry = {"guardrail_name": "my_guard", "guardrail_status": "success"} with trace.use_span(server, end_on_exit=False): with logger.start_phase_span("auth /chat/completions"): - logger._emit_guardrail_spans(request_data) + logger.emit_guardrail_span(entry) server.end() by_name = {s.name: s for s in exporter.get_finished_spans()} guard = by_name["execute_guardrail my_guard"] @@ -1188,37 +1181,29 @@ def test_boundary_span_closes_without_proxy_fanout(monkeypatch): # --------------------------------------------------------------------------- # -def _guardrail_request_data(*, start, end): +def _guardrail_entry(*, start, end): return { - "metadata": { - "standard_logging_guardrail_information": [ - { - "guardrail_name": "openai-moderation", - "guardrail_mode": "pre_call", - "guardrail_status": "success", - "start_time": start, - "end_time": end, - "duration": end - start, - } - ], - } + "guardrail_name": "openai-moderation", + "guardrail_mode": "pre_call", + "guardrail_status": "success", + "start_time": start, + "end_time": end, + "duration": end - start, } def test_guardrail_span_parents_to_ambient_server_span(): - """The post-call hook runs in the request task with the server span ambient, - so the guardrail span parents to it natively — no span threaded through - metadata. (Auth already finished, so no phase span is active.)""" + """``emit_guardrail_span`` runs in the request task with the server span + ambient, so with no explicit anchor set the guardrail span parents to it. + (Auth already finished, so no phase span is active.)""" logger, exporter = _logger() server = logger._emitter.start_span( SpanRole.PROXY_REQUEST, LITELLM_PROXY_REQUEST_SPAN_NAME ) - data = _guardrail_request_data(start=1000.0, end=1000.5) + entry = _guardrail_entry(start=1000.0, end=1000.5) try: with trace.use_span(server, end_on_exit=False): - asyncio.run( - logger.async_post_call_success_hook(data, _Auth(), {"ok": True}) - ) + logger.emit_guardrail_span(entry) finally: server.end() g = {s.name: s for s in exporter.get_finished_spans()}[ @@ -1229,17 +1214,15 @@ def test_guardrail_span_parents_to_ambient_server_span(): def test_guardrail_span_uses_actual_execution_timestamps(): """A pre_call guardrail's span carries its real start/end (from the logging - entry), so it sorts before the LLM call instead of at post-call emit time.""" + entry), so it sorts before the LLM call instead of at emission time.""" logger, exporter = _logger() server = logger._emitter.start_span( SpanRole.PROXY_REQUEST, LITELLM_PROXY_REQUEST_SPAN_NAME ) - data = _guardrail_request_data(start=1700.0, end=1700.25) + entry = _guardrail_entry(start=1700.0, end=1700.25) try: with trace.use_span(server, end_on_exit=False): - asyncio.run( - logger.async_post_call_success_hook(data, _Auth(), {"ok": True}) - ) + logger.emit_guardrail_span(entry) finally: server.end() g = {s.name: s for s in exporter.get_finished_spans()}[ @@ -1247,3 +1230,60 @@ def test_guardrail_span_uses_actual_execution_timestamps(): ] assert g.start_time == to_ns(1700.0) assert g.end_time == to_ns(1700.25) + + +def test_emit_guardrail_span_anchors_to_root_not_ambient_phase_span(): + """With an explicit request-root anchor set, the guardrail span parents to it + even while a phase span is the active OTel context — the anchor wins over + ambient, so a guardrail emitted mid-``auth`` is a sibling of the LLM call, not + a child of ``auth``.""" + logger, exporter = _logger() + server = logger._emitter.start_span( + SpanRole.PROXY_REQUEST, LITELLM_PROXY_REQUEST_SPAN_NAME + ) + set_request_root_span(server) + entry = _guardrail_entry(start=2000.0, end=2000.1) + with logger.start_phase_span("auth /chat/completions"): + logger.emit_guardrail_span(entry) + server.end() + by_name = {s.name: s for s in exporter.get_finished_spans()} + guard = by_name["execute_guardrail openai-moderation"] + auth_span = by_name["auth /chat/completions"] + assert guard.parent.span_id == server.get_span_context().span_id + assert guard.parent.span_id != auth_span.get_span_context().span_id + + +def test_module_level_emit_guardrail_span_routes_to_registered_logger(monkeypatch): + """The module-level entry point custom_guardrail calls routes the entry to the + single registered v2 logger and emits exactly one span.""" + import litellm.integrations.otel.logger as otel_logger + + logger, exporter = _logger() + monkeypatch.setattr(otel_logger, "_registered_v2_logger", lambda: logger) + + otel_logger.emit_guardrail_span(_guardrail_entry(start=3000.0, end=3000.2)) + + names = [s.name for s in exporter.get_finished_spans()] + assert names.count("execute_guardrail openai-moderation") == 1 + + +def test_module_level_emit_guardrail_span_noop_without_registered_logger(monkeypatch): + """No registered v2 logger (SDK path / OTel not configured) → emitting is a + no-op rather than an error.""" + import litellm.integrations.otel.logger as otel_logger + + monkeypatch.setattr(otel_logger, "_registered_v2_logger", lambda: None) + otel_logger.emit_guardrail_span(_guardrail_entry(start=1.0, end=2.0)) + + +def test_module_level_emit_guardrail_span_swallows_emit_errors(monkeypatch): + """Span emission is best-effort: a logger that raises must never propagate out + of the guardrail-recording path and break guardrail evaluation.""" + import litellm.integrations.otel.logger as otel_logger + + class _Boom: + def emit_guardrail_span(self, entry): + raise RuntimeError("emit blew up") + + monkeypatch.setattr(otel_logger, "_registered_v2_logger", lambda: _Boom()) + otel_logger.emit_guardrail_span(_guardrail_entry(start=1.0, end=2.0)) diff --git a/tests/test_litellm/integrations/test_custom_guardrail.py b/tests/test_litellm/integrations/test_custom_guardrail.py index a881044dc1..4956fccb8d 100644 --- a/tests/test_litellm/integrations/test_custom_guardrail.py +++ b/tests/test_litellm/integrations/test_custom_guardrail.py @@ -500,6 +500,65 @@ class TestGuardrailLoggingAggregation: assert info[1]["guardrail_name"] == "test_guardrail" +class TestGuardrailOtelSpanEmission: + """Recording a guardrail emits its otel span inline, so every guardrail + execution produces a span — including the pass-through allow path that never + reaches a post-call hook.""" + + def _make_guardrail(self): + from litellm.types.guardrails import GuardrailEventHooks + + return CustomGuardrail( + guardrail_name="emit_guard", + event_hook=GuardrailEventHooks.pre_call, + ) + + def _record(self, guardrail, request_data): + guardrail.add_standard_logging_guardrail_information_to_request_data( + guardrail_json_response={"result": "ok"}, + request_data=request_data, + guardrail_status="success", + start_time=1.0, + end_time=2.0, + duration=1.0, + ) + + def test_emits_span_for_recorded_entry(self, monkeypatch): + captured = [] + monkeypatch.setattr( + "litellm.integrations.otel.logger.emit_guardrail_span", + captured.append, + ) + + request_data = {"metadata": {}} + self._record(self._make_guardrail(), request_data) + + assert len(captured) == 1 + emitted = captured[0] + recorded = request_data["metadata"]["standard_logging_guardrail_information"][ + -1 + ] + assert emitted is recorded + assert emitted["guardrail_name"] == "emit_guard" + assert emitted["start_time"] == 1.0 + assert emitted["end_time"] == 2.0 + + def test_span_emission_failure_does_not_break_recording(self, monkeypatch): + def _boom(_entry): + raise RuntimeError("otel exporter down") + + monkeypatch.setattr( + "litellm.integrations.otel.logger.emit_guardrail_span", _boom + ) + + request_data = {"metadata": {}} + self._record(self._make_guardrail(), request_data) + + info = request_data["metadata"]["standard_logging_guardrail_information"] + assert len(info) == 1 + assert info[0]["guardrail_name"] == "emit_guard" + + class TestGuardrailSensitiveFieldStripping: """Tests that secret_fields is stripped from guardrail responses before logging. diff --git a/tests/test_litellm/integrations/test_opentelemetry.py b/tests/test_litellm/integrations/test_opentelemetry.py index c4500bd613..f6dee9b64c 100644 --- a/tests/test_litellm/integrations/test_opentelemetry.py +++ b/tests/test_litellm/integrations/test_opentelemetry.py @@ -1761,6 +1761,31 @@ class TestOpenTelemetry(unittest.TestCase): mock_tracer.start_span.assert_not_called() +class TestOpenTelemetryToNs(unittest.TestCase): + """``_to_ns`` converts a span boundary to epoch nanoseconds. Service spans now + feed it real float/datetime windows, and a missing boundary arrives as + ``None`` — all three shapes must convert without raising the ``AttributeError`` + a bare ``dt.timestamp()`` would on a float or ``None``.""" + + def setUp(self): + self.otel = OpenTelemetry() + + def test_datetime_converts_to_epoch_ns(self): + dt = datetime(2026, 5, 26, 12, 0, 0, tzinfo=timezone.utc) + self.assertEqual(self.otel._to_ns(dt), int(dt.timestamp() * 1e9)) + + def test_float_epoch_seconds_scaled_to_ns(self): + self.assertEqual(self.otel._to_ns(1700.5), 1_700_500_000_000) + + def test_int_epoch_seconds_scaled_to_ns(self): + self.assertEqual(self.otel._to_ns(1700), 1_700_000_000_000) + + @patch("litellm.integrations.opentelemetry.datetime") + def test_none_falls_back_to_current_time(self, mock_datetime): + mock_datetime.now.return_value.timestamp.return_value = 1700.0 + self.assertEqual(self.otel._to_ns(None), 1_700_000_000_000) + + class TestOpenTelemetryHeaderSplitting(unittest.TestCase): """Test suite for _get_headers_dictionary method""" diff --git a/tests/test_litellm/proxy/pass_through_endpoints/test_passthrough_guardrail_block_otel_span.py b/tests/test_litellm/proxy/pass_through_endpoints/test_passthrough_guardrail_block_otel_span.py index 9009da88af..73927e92c1 100644 --- a/tests/test_litellm/proxy/pass_through_endpoints/test_passthrough_guardrail_block_otel_span.py +++ b/tests/test_litellm/proxy/pass_through_endpoints/test_passthrough_guardrail_block_otel_span.py @@ -1,13 +1,14 @@ """Regression: a guardrail block on a passthrough endpoint must still emit the otel guardrail span. -Before the fix the post-call guardrail recorded its -``standard_logging_guardrail_information`` onto a throwaway ``hook_data`` dict, -which the failure handler discarded. So ``pass_through_request`` forwarded a -``request_data`` without it to ``post_call_failure_hook`` and the otel guardrail -span (emitted from that hook) was present on allow but missing on block. The -unified path always has it. These tests drive the real ``pass_through_request`` -with a real ``ProxyLogging`` + a real otel V2 logger and assert the span is +The span is emitted from the guardrail-recording path the moment a guardrail +finishes (``add_standard_logging_guardrail_information_to_request_data`` -> +``emit_guardrail_span``), routed through the proxy's registered otel V2 logger, +rather than from a post-call hook that does not fire on every path. A block +raises out of the post-call hook before any later hook runs, so the recording +path is the only place the span is reliably produced. These tests drive the real +``pass_through_request`` with a real ``ProxyLogging`` + a real otel V2 logger +registered as the proxy's ``open_telemetry_logger`` and assert the span is emitted on both allow and block. """ @@ -141,6 +142,7 @@ async def _drive(response_text: str): ), patch(f"{_PT_MOD}._is_streaming_response", return_value=False), patch("litellm.proxy.proxy_server.proxy_logging_obj", proxy_logging), + patch("litellm.proxy.proxy_server.open_telemetry_logger", otel), patch("litellm.proxy.proxy_server.llm_router", None), patch(f"{_PT_MOD}.pass_through_endpoint_logging", mock_pt_logging), patch(f"{_PT_MOD}.get_async_httpx_client", return_value=mock_async_client_obj), diff --git a/tests/test_litellm/test_service_logger.py b/tests/test_litellm/test_service_logger.py index 34fe73382b..de46403b64 100644 --- a/tests/test_litellm/test_service_logger.py +++ b/tests/test_litellm/test_service_logger.py @@ -99,6 +99,33 @@ async def test_async_log_success_event_should_handle_float_duration(): assert call_kwargs.kwargs["duration"] == 1.5 +@pytest.mark.asyncio +async def test_async_log_success_event_forwards_start_and_end_time(): + """The LITELLM service span must carry its real execution window, so + ``async_log_success_event`` forwards ``start_time``/``end_time`` to the service + hook. Without forwarding, the span emits with a synthetic now() boundary + instead of the call's actual timing.""" + service_logger = ServiceLogging(mock_testing=True) + + start_time = datetime(2026, 2, 13, 22, 35, 0) + end_time = datetime(2026, 2, 13, 22, 35, 1) + + with patch.object( + service_logger, "async_service_success_hook", new_callable=AsyncMock + ) as mock_hook: + await service_logger.async_log_success_event( + kwargs={"call_type": "completion"}, + response_obj=None, + start_time=start_time, + end_time=end_time, + ) + + mock_hook.assert_called_once() + forwarded = mock_hook.call_args.kwargs + assert forwarded["start_time"] == start_time + assert forwarded["end_time"] == end_time + + # --------------------------------------------------------------------------- # # V2 OpenTelemetry service-span dispatch (regression: service spans were always # dropped because the dispatch only recognized the legacy OpenTelemetry class).