From 93678af0978477731df39a0bb8bfc65bb513135e Mon Sep 17 00:00:00 2001 From: narmstrong-berri Date: Fri, 6 Nov 2026 09:07:09 +0000 Subject: [PATCH] fix(messages): log the sent messages and the caller's params on native messages calls Python updates model_call_details with the transformed request body before pre_call, so the logged messages are what was sent. The native adapter kept the caller's messages and compared the caller's params to the sent ones as JSON values, so an int 0 logged as 0.0 --- .../callbacks-legacy-python/src/adapter.rs | 53 +++++++++++++++++-- .../src/test_support.rs | 1 + .../messages/test_callbacks.py | 24 +++++++++ 3 files changed, 75 insertions(+), 3 deletions(-) diff --git a/litellm-rust/crates/callbacks-legacy-python/src/adapter.rs b/litellm-rust/crates/callbacks-legacy-python/src/adapter.rs index 1bb84184e4c..2261770df26 100644 --- a/litellm-rust/crates/callbacks-legacy-python/src/adapter.rs +++ b/litellm-rust/crates/callbacks-legacy-python/src/adapter.rs @@ -137,6 +137,40 @@ impl LegacyLogging { Some(params) } + // Compared as Python compares them, so a caller's `0` is kept over a typed float's `0.0`. + fn caller_value<'py>( + &self, + py: Python<'py>, + name: &str, + sent: &Value, + ) -> PyResult>> { + match self.call.lookup(py, name)? { + Some(value) if from_py::(&value).is_ok() && value.eq(to_py(py, sent)?)? => { + Ok(Some(value)) + } + _ => Ok(None), + } + } + + // Python's Messages handler logs the caller's own optional params, not their typed copies. + fn as_called(&self, py: Python<'_>, context: &RequestContext) -> PyResult { + let mut context = context.clone(); + if self.operation != LoggingOperation::Messages { + return Ok(context); + } + for (name, sent) in context + .optional_params + .as_object_mut() + .into_iter() + .flatten() + { + if let Some(value) = self.caller_value(py, name, sent)? { + *sent = from_py(&value)?; + } + } + Ok(context) + } + /// Python times the provider exchange inside the async `AsyncHTTPHandler.post`; its sync /// client is untimed. fn close_api_window(&mut self, py: Python<'_>, end: f64) -> PyResult<()> { @@ -442,6 +476,7 @@ impl LegacyLogging { wire: Box, context: &RequestContext, ) -> PyResult>> { + let context = &self.as_called(py, context)?; let logger = self.logger()?; logger.update_from_kwargs( py, @@ -454,12 +489,17 @@ impl LegacyLogging { .into_bound(py) .cast_into::()?; for (name, sent) in wire.body.as_object().into_iter().flatten() { - if let Some(value) = self.call.lookup(py, name)? - && from_py::(&value).is_ok_and(|caller| caller == *sent) - { + if let Some(value) = self.caller_value(py, name, sent)? { body.set_item(name, value)?; } } + if self.operation == LoggingOperation::Messages { + // Python's Messages handler merges its transformed request body into the call details. + logger + .object(py) + .getattr("model_call_details")? + .call_method1("update", (&body,))?; + } let headers = PyDict::new(py); for (name, value) in &wire.headers { headers.set_item(name, value)?; @@ -550,6 +590,13 @@ impl LegacyLogging { }; details.set_item("cache_hit", self.cache_key.is_some())?; details.set_item("cache_key", self.cache_key.as_deref())?; + // The refresh above reset the details Python's handler took from its request body; a cache + // hit never reaches that handler, so it keeps the caller's. + if let (LoggingOperation::Messages, ResultSource::Provider, Some(request)) = + (self.operation, &facts.source, &self.request) + { + details.call_method1("update", (request.body.bind(py),))?; + } Ok(HookStep::Ready(())) } diff --git a/litellm-rust/crates/callbacks-legacy-python/src/test_support.rs b/litellm-rust/crates/callbacks-legacy-python/src/test_support.rs index 8acfa7a898b..498c8bb8900 100644 --- a/litellm-rust/crates/callbacks-legacy-python/src/test_support.rs +++ b/litellm-rust/crates/callbacks-legacy-python/src/test_support.rs @@ -129,6 +129,7 @@ class StubCoroutine: class StubLogger: def __init__(self): self.calls = [] + self.model_call_details = {} self.hooks = {} self.on_enqueue = lambda coroutine: None diff --git a/tests/test_litellm_rust/messages/test_callbacks.py b/tests/test_litellm_rust/messages/test_callbacks.py index e02fcd000e6..45b94b78d4e 100644 --- a/tests/test_litellm_rust/messages/test_callbacks.py +++ b/tests/test_litellm_rust/messages/test_callbacks.py @@ -157,6 +157,30 @@ async def test_success_event_logs_the_requested_reasoning_effort_not_its_transla assert logged["model_parameters"] == {"max_tokens": 64, "stream": False, "reasoning_effort": "low"} +@pytest.mark.asyncio +async def test_success_event_logs_the_sent_messages_and_the_callers_params(server: RecordingServer) -> None: + recorder: Final = RecordingLogger() + tool_use: Final = {"type": "tool_use", "id": "functions.Bash:0", "name": "bash", "input": {"command": "ls"}} + messages: Final = [ + {"role": "user", "content": "List /tmp"}, + {"role": "assistant", "content": [{"type": "text", "text": " \n"}, tool_use]}, + {"role": "user", "content": [{"type": "tool_result", "tool_use_id": "functions.Bash:0", "content": "a"}]}, + ] + + with rebound(litellm, "callbacks", [recorder]): + response: Final = await call(server, messages=messages, temperature=1) + success: Final = await recorder.wait_for_async("async_log_success_event") + + assert_served_natively(server, response) + sent: Final = server.requests[0].body + assert isinstance(sent, dict) + assert sent["messages"][1]["content"] == [{**tool_use, "id": "functions_Bash_0"}] + assert isinstance(success[0].kwargs, dict) + logged: Final = _OBJECT.validate_python(success[0].kwargs["standard_logging_object"]) + assert logged["messages"] == sent["messages"] + assert repr(_OBJECT.validate_python(logged["model_parameters"])["temperature"]) == "1" + + @pytest.mark.asyncio async def test_logging_hook_and_redaction_edits_reach_the_async_success_event(server: RecordingServer) -> None: class Rewrite(HookRecorder):