mirror of
https://github.com/BerriAI/litellm.git
synced 2026-11-11 08:38:24 +00:00
fix(logging): scrub the prompt out of SDK failure logs when message logging is redacted
This commit is contained in:
parent
85067355f5
commit
a32854a516
6 changed files with 265 additions and 9 deletions
|
|
@ -1,9 +1,11 @@
|
|||
import json
|
||||
import threading
|
||||
from collections.abc import Mapping
|
||||
from typing import TYPE_CHECKING, Any, Final
|
||||
|
||||
from litellm._logging import verbose_logger
|
||||
from litellm.integrations.custom_logger import CustomLogger
|
||||
from litellm.litellm_core_utils.redact_messages import scrubbed_exception_text
|
||||
|
||||
if TYPE_CHECKING:
|
||||
from litellm.types.utils import StandardLoggingPayload
|
||||
|
|
@ -74,7 +76,7 @@ class MlflowLogger(CustomLogger):
|
|||
async def async_log_failure_event(self, kwargs, response_obj, start_time, end_time):
|
||||
self._handle_failure(kwargs, response_obj, start_time, end_time)
|
||||
|
||||
def _handle_failure(self, kwargs, response_obj, start_time, end_time):
|
||||
def _handle_failure(self, kwargs: Mapping[str, object], response_obj, start_time, end_time):
|
||||
"""
|
||||
Log the failure event as an MLflow span.
|
||||
Note that this method is called *synchronously* unlike the success handler.
|
||||
|
|
@ -88,7 +90,19 @@ class MlflowLogger(CustomLogger):
|
|||
|
||||
# Record exception info as event
|
||||
if exception := kwargs.get("exception"):
|
||||
span.add_event(SpanEvent.from_exception(exception))
|
||||
scrubbed: Final = scrubbed_exception_text(kwargs)
|
||||
span.add_event(
|
||||
SpanEvent.from_exception(exception)
|
||||
if scrubbed is None
|
||||
else SpanEvent(
|
||||
name="exception",
|
||||
attributes={
|
||||
"exception.message": scrubbed[0],
|
||||
"exception.type": exception.__class__.__name__,
|
||||
"exception.stacktrace": scrubbed[1],
|
||||
},
|
||||
)
|
||||
)
|
||||
|
||||
self._extract_and_set_chat_attributes(span, kwargs, response_obj)
|
||||
self._end_span_or_trace(
|
||||
|
|
|
|||
|
|
@ -36,6 +36,7 @@ from litellm.integrations.otel.model.semconv import LiteLLM, Metric
|
|||
from litellm.integrations.otel.plumbing.otlp_tls import resolve_otlp_http_tls
|
||||
from litellm.integrations.otel.routing import routing_decision_attributes
|
||||
from litellm.litellm_core_utils.internal_call_metadata import is_unbilled_non_inference_call_from_params
|
||||
from litellm.litellm_core_utils.redact_messages import scrubbed_exception_text
|
||||
from litellm.litellm_core_utils.safe_json_dumps import safe_dumps
|
||||
from litellm.litellm_core_utils.secret_redaction import redact_string
|
||||
from litellm.litellm_core_utils.service_tier_utils import (
|
||||
|
|
@ -2271,9 +2272,13 @@ class OpenTelemetry(OTELGenAISemconvMixin, CustomLogger):
|
|||
|
||||
# Get the exception object if available
|
||||
exception: Final = kwargs.get("exception")
|
||||
scrubbed: Final = scrubbed_exception_text(kwargs)
|
||||
|
||||
# Record the exception using OTEL's standard method
|
||||
if exception is not None:
|
||||
if exception is not None and scrubbed is not None:
|
||||
span.record_exception(
|
||||
exception, attributes={"exception.message": scrubbed[0], "exception.stacktrace": scrubbed[1]}
|
||||
)
|
||||
elif exception is not None:
|
||||
span.record_exception(exception)
|
||||
|
||||
# Get StandardLoggingPayload for structured error information
|
||||
|
|
|
|||
|
|
@ -143,10 +143,15 @@ from litellm.litellm_core_utils.logging_utils import (
|
|||
from litellm.litellm_core_utils.model_param_helper import ModelParamHelper
|
||||
from litellm.litellm_core_utils.ptu_pricing import is_spilled_over_ptu_request
|
||||
from litellm.litellm_core_utils.redact_messages import (
|
||||
failure_request_texts,
|
||||
redact_message_input_output_from_custom_logger,
|
||||
redact_message_input_output_from_logging,
|
||||
redacted_model_call_details_for_custom_logger,
|
||||
redacted_response_obj_for_custom_logger,
|
||||
scrub_request_text,
|
||||
scrubbed_error_fields,
|
||||
scrubbed_exception_text,
|
||||
should_redact_failure_logging,
|
||||
should_redact_message_logging,
|
||||
)
|
||||
from litellm.litellm_core_utils.served_output_texts import (
|
||||
|
|
@ -4552,8 +4557,9 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
|
||||
self.model_call_details["log_event_type"] = "failed_api_call"
|
||||
self.model_call_details["exception"] = exception
|
||||
traceback_text: Final = redact_string(traceback_exception) if isinstance(traceback_exception, str) else None
|
||||
self.model_call_details["traceback_exception"] = (
|
||||
redact_string(traceback_exception) if isinstance(traceback_exception, str) else traceback_exception
|
||||
traceback_exception if traceback_text is None else traceback_text
|
||||
)
|
||||
self.model_call_details["end_time"] = end_time
|
||||
self.model_call_details.setdefault("original_response", None)
|
||||
|
|
@ -4571,9 +4577,15 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
metadata: Final = self.model_call_details["litellm_params"].get("metadata", {}) or {}
|
||||
metadata.update(exception.headers)
|
||||
|
||||
# Building the payload redacts the messages in place, so read the request text first
|
||||
redact: Final = should_redact_failure_logging(self.model_call_details)
|
||||
request_texts: Final[frozenset[str]] = (
|
||||
failure_request_texts(self.model_call_details, getattr(self, "messages", None)) if redact else frozenset()
|
||||
)
|
||||
|
||||
## STANDARDIZED LOGGING PAYLOAD
|
||||
|
||||
self.model_call_details["standard_logging_object"] = get_standard_logging_object_payload(
|
||||
payload: Final = get_standard_logging_object_payload(
|
||||
kwargs=self.model_call_details,
|
||||
init_response_obj={},
|
||||
start_time=start_time,
|
||||
|
|
@ -4584,6 +4596,11 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
original_exception=exception,
|
||||
standard_built_in_tools_params=self.standard_built_in_tools_params,
|
||||
)
|
||||
self.model_call_details["standard_logging_object"] = (
|
||||
{**payload, **scrubbed_error_fields(payload, request_texts)} if redact and payload is not None else payload
|
||||
)
|
||||
if redact and traceback_text is not None:
|
||||
self.model_call_details["traceback_exception"] = scrub_request_text(traceback_text, request_texts)
|
||||
return start_time, end_time
|
||||
|
||||
async def special_failure_handlers(self, exception: Exception):
|
||||
|
|
@ -4679,6 +4696,9 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
)
|
||||
)
|
||||
self.mark_logging_complete(event_type="sync_failure")
|
||||
scrubbed_exception: Final = scrubbed_exception_text(self.model_call_details)
|
||||
logged_error: Final = str(exception) if scrubbed_exception is None else scrubbed_exception[0]
|
||||
logged_traceback: Final = traceback_exception if scrubbed_exception is None else scrubbed_exception[1]
|
||||
for callback in callbacks:
|
||||
try:
|
||||
should_run = self.should_run_callback(
|
||||
|
|
@ -4704,7 +4724,7 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
user_id=self._model_call_details_view.get("user", "default"),
|
||||
model=model,
|
||||
input=input,
|
||||
error=traceback_exception,
|
||||
error=logged_traceback,
|
||||
run_id=self.litellm_call_id,
|
||||
start_time=start_time,
|
||||
end_time=end_time,
|
||||
|
|
@ -4771,7 +4791,7 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
end_time=end_time,
|
||||
response_obj=None,
|
||||
user_id=kwargs.get("user", None),
|
||||
status_message=str(exception),
|
||||
status_message=logged_error,
|
||||
level="ERROR",
|
||||
kwargs=kwargs,
|
||||
)
|
||||
|
|
@ -4790,7 +4810,7 @@ class Logging(LiteLLMLoggingBaseClass):
|
|||
response_obj=None,
|
||||
user_id=self.model_call_details.get("user", None),
|
||||
print_verbose=print_verbose,
|
||||
status_message=str(exception),
|
||||
status_message=logged_error,
|
||||
level="ERROR",
|
||||
kwargs=self.model_call_details,
|
||||
)
|
||||
|
|
|
|||
|
|
@ -268,3 +268,54 @@ def test_mlflow_end_span_or_trace_works_with_mlflow_2x_client():
|
|||
span=child_span, outputs="out", end_time_ns=1, status="OK"
|
||||
)
|
||||
assert client.ended_spans == [("req-2", "span-2")]
|
||||
|
||||
|
||||
class _ExceptionSpanEvent:
|
||||
def __init__(self, name, attributes):
|
||||
self.name = name
|
||||
self.attributes = attributes
|
||||
|
||||
@classmethod
|
||||
def from_exception(cls, exception):
|
||||
return cls(
|
||||
"exception",
|
||||
{
|
||||
"exception.message": str(exception),
|
||||
"exception.type": type(exception).__name__,
|
||||
"exception.stacktrace": "raw",
|
||||
},
|
||||
)
|
||||
|
||||
|
||||
@pytest.mark.parametrize("scrubbed", [True, False], ids=["scrubbed", "not_scrubbed"])
|
||||
def test_mlflow_failure_event_records_the_error_text_the_payload_logged(scrubbed):
|
||||
secret = "my ssn is 123-45-6789"
|
||||
modules = _mock_mlflow_modules()
|
||||
modules["mlflow.entities"].SpanEvent = _ExceptionSpanEvent
|
||||
with patch.dict("sys.modules", modules):
|
||||
from litellm.integrations.mlflow import MlflowLogger
|
||||
|
||||
mlflow_logger = MlflowLogger()
|
||||
span = MagicMock()
|
||||
mlflow_logger._start_span_or_trace = MagicMock(return_value=span)
|
||||
mlflow_logger._end_span_or_trace = MagicMock()
|
||||
mlflow_logger._extract_and_set_chat_attributes = MagicMock()
|
||||
error_message = "bad input: redacted-by-litellm" if scrubbed else f"bad input: {secret}"
|
||||
|
||||
mlflow_logger._handle_failure(
|
||||
kwargs={
|
||||
"litellm_call_id": "x",
|
||||
"exception": ValueError(f"bad input: {secret}"),
|
||||
"standard_logging_object": {
|
||||
"error_information": {"error_message": error_message, "traceback": "frames"}
|
||||
},
|
||||
},
|
||||
response_obj=None,
|
||||
start_time=datetime(2025, 1, 1),
|
||||
end_time=datetime(2025, 1, 1),
|
||||
)
|
||||
|
||||
event = span.add_event.call_args.args[0]
|
||||
assert event.attributes["exception.type"] == "ValueError"
|
||||
assert event.attributes["exception.message"] == error_message
|
||||
assert event.attributes["exception.stacktrace"] == ("frames" if scrubbed else "raw")
|
||||
|
|
|
|||
|
|
@ -7636,3 +7636,39 @@ class TestOpentelemetryUnitTests:
|
|||
|
||||
# Assert: error.message should be set from error_str using ErrorAttributes constant
|
||||
mock_span.set_attribute.assert_called_with(ErrorAttributes.ERROR_MESSAGE, "Fallback error message")
|
||||
|
||||
|
||||
def test_record_exception_on_span_records_the_scrubbed_error_text_with_the_same_event_shape():
|
||||
from opentelemetry.sdk.trace import TracerProvider
|
||||
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
|
||||
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter
|
||||
|
||||
from litellm.integrations.opentelemetry import OpenTelemetry
|
||||
|
||||
exporter = InMemorySpanExporter()
|
||||
provider = TracerProvider()
|
||||
provider.add_span_processor(SimpleSpanProcessor(exporter))
|
||||
secret = "my ssn is 123-45-6789"
|
||||
exception = ValueError(f"bad input: {secret}")
|
||||
|
||||
with provider.get_tracer(__name__).start_as_current_span("failure") as span:
|
||||
OpenTelemetry()._record_exception_on_span(
|
||||
span=span,
|
||||
kwargs={
|
||||
"exception": exception,
|
||||
"standard_logging_object": {
|
||||
"error_information": {
|
||||
"error_class": "ValueError",
|
||||
"error_message": "bad input: redacted-by-litellm",
|
||||
"traceback": "frames",
|
||||
},
|
||||
},
|
||||
},
|
||||
)
|
||||
|
||||
(event,) = exporter.get_finished_spans()[0].events
|
||||
assert secret not in str(dict(event.attributes))
|
||||
assert event.attributes["exception.message"] == "bad input: redacted-by-litellm"
|
||||
assert event.attributes["exception.stacktrace"] == "frames"
|
||||
assert event.attributes["exception.type"] == "ValueError"
|
||||
assert event.attributes["exception.escaped"] == "False"
|
||||
|
|
|
|||
|
|
@ -12049,6 +12049,136 @@ def test_uncached_price_keeps_an_earlier_price_failure(pr44187_priced_model: str
|
|||
assert logging_obj.model_call_details["response_cost_failure_debug_information"] == earlier_failure
|
||||
|
||||
|
||||
SCRUB_PROMPT: Final = "my ssn is 123-45-6789"
|
||||
|
||||
|
||||
class _FailureCapture(CustomLogger):
|
||||
def __init__(self, **kwargs: bool) -> None:
|
||||
super().__init__(**kwargs)
|
||||
self.sync_kwargs: dict | None = None
|
||||
self.async_kwargs: dict | None = None
|
||||
|
||||
def log_failure_event(self, kwargs, response_obj, start_time, end_time):
|
||||
self.sync_kwargs = kwargs
|
||||
|
||||
async def async_log_failure_event(self, kwargs, response_obj, start_time, end_time):
|
||||
self.async_kwargs = kwargs
|
||||
|
||||
|
||||
def _prompt_failure_logging_obj(litellm_params: Mapping[str, object] | None = None) -> LitellmLogging:
|
||||
logging_obj: Final = LitellmLogging(
|
||||
model="gpt-4o",
|
||||
messages=[{"role": "user", "content": SCRUB_PROMPT}],
|
||||
stream=False,
|
||||
call_type="completion",
|
||||
start_time=datetime.datetime(2025, 1, 1),
|
||||
litellm_call_id="failure-scrub",
|
||||
function_id="failure-scrub",
|
||||
)
|
||||
logging_obj.model_call_details["messages"] = logging_obj.messages # as update_environment_variables sets it
|
||||
if litellm_params is not None:
|
||||
logging_obj.model_call_details["litellm_params"] = dict(litellm_params)
|
||||
return logging_obj
|
||||
|
||||
|
||||
def _prompt_echo_error() -> litellm.BadRequestError:
|
||||
return litellm.BadRequestError(
|
||||
message=f"Invalid message passed in {{'role': 'user', 'content': '{SCRUB_PROMPT}'}}",
|
||||
model="gpt-4o",
|
||||
llm_provider="openai",
|
||||
)
|
||||
|
||||
|
||||
async def _async_failure_payload(
|
||||
monkeypatch: pytest.MonkeyPatch, *, redact: bool, error: Exception, capture: _FailureCapture | None = None
|
||||
) -> dict:
|
||||
logger: Final = capture or _FailureCapture()
|
||||
monkeypatch.setattr(litellm, "turn_off_message_logging", redact)
|
||||
monkeypatch.setattr(litellm, "_async_failure_callback", [logger])
|
||||
await _prompt_failure_logging_obj().async_failure_handler(error, f"Traceback: {error}")
|
||||
assert logger.async_kwargs is not None
|
||||
return logger.async_kwargs
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_failure_with_redaction_on_scrubs_the_prompt_out_of_the_error_and_keeps_the_rest(monkeypatch):
|
||||
kwargs: Final = await _async_failure_payload(monkeypatch, redact=True, error=_prompt_echo_error())
|
||||
|
||||
payload: Final = kwargs["standard_logging_object"]
|
||||
assert SCRUB_PROMPT not in json.dumps(payload, default=str)
|
||||
assert SCRUB_PROMPT not in kwargs["traceback_exception"]
|
||||
assert "Invalid message passed in" in payload["error_str"]
|
||||
assert "'content': 'redacted-by-litellm'" in payload["error_information"]["error_message"]
|
||||
assert payload["error_information"]["error_class"] == "BadRequestError"
|
||||
assert payload["error_information"]["error_code"] == "400"
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_failure_with_redaction_on_keeps_error_text_that_does_not_quote_the_prompt(monkeypatch):
|
||||
error: Final = litellm.AuthenticationError(
|
||||
message="Incorrect API key provided", model="gpt-4o", llm_provider="openai"
|
||||
)
|
||||
|
||||
redacted: Final = (await _async_failure_payload(monkeypatch, redact=True, error=error))["standard_logging_object"]
|
||||
raw: Final = (await _async_failure_payload(monkeypatch, redact=False, error=error))["standard_logging_object"]
|
||||
|
||||
assert redacted["error_str"] == raw["error_str"]
|
||||
assert redacted["error_information"] == raw["error_information"]
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_failure_with_redaction_off_logs_the_error_as_raised(monkeypatch):
|
||||
kwargs: Final = await _async_failure_payload(monkeypatch, redact=False, error=_prompt_echo_error())
|
||||
|
||||
assert SCRUB_PROMPT in kwargs["standard_logging_object"]["error_information"]["error_message"]
|
||||
assert SCRUB_PROMPT in kwargs["traceback_exception"]
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
@pytest.mark.parametrize("headers", [None, "x", ["a"]], ids=["none", "str", "list"])
|
||||
@pytest.mark.parametrize("redact", [True, False], ids=["redaction_on", "redaction_off"])
|
||||
async def test_failure_with_non_mapping_headers_is_still_logged(monkeypatch, headers, redact):
|
||||
capture: Final = _FailureCapture()
|
||||
monkeypatch.setattr(litellm, "turn_off_message_logging", redact)
|
||||
monkeypatch.setattr(litellm, "_async_failure_callback", [capture])
|
||||
logging_obj: Final = _prompt_failure_logging_obj({"metadata": {"headers": headers}})
|
||||
|
||||
await logging_obj.async_failure_handler(_prompt_echo_error(), f"Traceback: {SCRUB_PROMPT}")
|
||||
|
||||
assert capture.async_kwargs is not None
|
||||
assert (SCRUB_PROMPT in capture.async_kwargs["traceback_exception"]) is not redact
|
||||
|
||||
|
||||
def test_sync_failure_hands_callbacks_and_langfuse_the_scrubbed_error(monkeypatch):
|
||||
capture: Final = _FailureCapture()
|
||||
langfuse: Final = MagicMock()
|
||||
monkeypatch.setattr(litellm, "turn_off_message_logging", True)
|
||||
monkeypatch.setattr(litellm, "failure_callback", [capture, "langfuse"])
|
||||
monkeypatch.setattr(litellm_logging, "langFuseLogger", langfuse)
|
||||
|
||||
_prompt_failure_logging_obj().failure_handler(_prompt_echo_error(), f"Traceback: {SCRUB_PROMPT}")
|
||||
|
||||
assert capture.sync_kwargs is not None
|
||||
assert SCRUB_PROMPT not in json.dumps(capture.sync_kwargs["standard_logging_object"], default=str)
|
||||
status_message: Final = langfuse.log_event_on_langfuse.call_args.kwargs["status_message"]
|
||||
assert "Invalid message passed in" in status_message
|
||||
assert SCRUB_PROMPT not in status_message
|
||||
|
||||
|
||||
def test_sync_failure_hands_lunary_the_scrubbed_traceback_when_only_the_traceback_quotes_the_prompt(monkeypatch):
|
||||
lunary: Final = MagicMock()
|
||||
monkeypatch.setattr(litellm, "turn_off_message_logging", True)
|
||||
monkeypatch.setattr(litellm, "failure_callback", ["lunary"])
|
||||
monkeypatch.setattr(litellm_logging, "lunaryLogger", lunary)
|
||||
error: Final = litellm.APIConnectionError(message="Connection failed", model="gpt-4o", llm_provider="openai")
|
||||
|
||||
_prompt_failure_logging_obj().failure_handler(error, f"ValueError: bad input {SCRUB_PROMPT}\n\n{error}")
|
||||
|
||||
logged_error: Final = lunary.log_event.call_args.kwargs["error"]
|
||||
assert "ValueError: bad input redacted-by-litellm" in logged_error
|
||||
assert SCRUB_PROMPT not in logged_error
|
||||
|
||||
|
||||
def test_enterprise_alerting_loggers_resolves_real_classes():
|
||||
from litellm_enterprise.enterprise_callbacks.pagerduty.pagerduty import PagerDutyAlerting
|
||||
from litellm_enterprise.enterprise_callbacks.send_emails.resend_email import ResendEmailLogger
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue