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
This commit is contained in:
narmstrong-berri 2026-11-06 09:07:09 +00:00
parent a67684d814
commit 93678af097
No known key found for this signature in database
3 changed files with 75 additions and 3 deletions

View file

@ -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<Option<Bound<'py, PyAny>>> {
match self.call.lookup(py, name)? {
Some(value) if from_py::<Value>(&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<RequestContext> {
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<WireRequest>,
context: &RequestContext,
) -> PyResult<HookStep<Self, Box<WireRequest>>> {
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::<PyDict>()?;
for (name, sent) in wire.body.as_object().into_iter().flatten() {
if let Some(value) = self.call.lookup(py, name)?
&& from_py::<Value>(&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(()))
}

View file

@ -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

View file

@ -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):