mirror of
https://github.com/tiennm99/litellm.git
synced 2026-07-18 02:17:35 +00:00
fix: missing span for guardrail passthrough (#29552)
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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):
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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.
|
||||
|
||||
|
||||
@@ -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))
|
||||
|
||||
@@ -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.
|
||||
|
||||
|
||||
@@ -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"""
|
||||
|
||||
|
||||
+9
-7
@@ -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),
|
||||
|
||||
@@ -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).
|
||||
|
||||
Reference in New Issue
Block a user