Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
73 changes: 73 additions & 0 deletions src/harness/agent_loop/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -2165,3 +2165,76 @@ async fn mock_streaming_script_invoke_folds_items_to_response() {
.expect("fold succeeds");
assert_eq!(response.text(), "abcd");
}

#[tokio::test]
async fn tool_completed_event_carries_outcome() {
use crate::harness::events::RecordingListener;

// A tool that fails: its ToolCompleted event must carry the failure message,
// a real duration, and the output size — from the event itself, not a
// side-channel — so journal-backed exporters can render the outcome.
struct FailTool;
#[async_trait]
impl Tool<()> for FailTool {
fn name(&self) -> &str {
"boom"
}
fn description(&self) -> &str {
"always fails"
}
fn schema(&self) -> ToolSchema {
ToolSchema::new("boom", "always fails", json!({ "type": "object" }))
}
async fn call(&self, _state: &(), call: ToolCall) -> Result<ToolResult> {
Ok(ToolResult {
call_id: call.id,
name: "boom".to_string(),
content: "nope".to_string(),
raw: None,
error: Some("kaboom".to_string()),
elapsed_ms: 0,
})
}
}

let mut harness: AgentHarness<()> = AgentHarness::new();
harness.register_model(
"mock",
Arc::new(MockModel::with_responses(vec![
tool_call_response("c1", "boom", json!({})),
text_response("done", 1, 1),
])),
);
harness.register_tool(Arc::new(FailTool));

let recorder = Arc::new(RecordingListener::new());
let ctx: RunContext<()> = RunContext::new(RunConfig::new("run-tc"), ());
ctx.events.subscribe(recorder.clone());
harness
.invoke_in_context(&(), ctx, vec![Message::user("go")])
.await
.expect("run succeeds");

let (error, duration_ms, output_bytes) = recorder
.events()
.into_iter()
.find_map(|record| match record.event {
AgentEvent::ToolCompleted {
tool_name,
error,
duration_ms,
output_bytes,
..
} if tool_name == "boom" => Some((error, duration_ms, output_bytes)),
_ => None,
})
.expect("a ToolCompleted event for `boom`");

assert_eq!(
error.as_deref(),
Some("kaboom"),
"failure message on the event"
);
assert!(duration_ms.is_some(), "wall-clock duration present");
assert_eq!(output_bytes, Some(4), "\"nope\".len() == 4");
}
10 changes: 10 additions & 0 deletions src/harness/agent_loop/tools.rs
Original file line number Diff line number Diff line change
Expand Up @@ -260,12 +260,22 @@ impl<State: Send + Sync, Ctx: Send + Sync> AgentHarness<State, Ctx> {
.capture
.tool_io
.then(|| Value::String(result.content.clone()));
// Outcome fields carried on the event itself (not a side-channel) so
// journal-backed exporters render duration/size/success without the
// live run's state. Duration is wall-clock (completion minus start);
// `error` mirrors `ToolResult::error` (`None` == success).
let duration_ms = crate::harness::ids::now_ms().saturating_sub(prepared.started_at_ms);

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Stamp tool duration at actual completion

When a turn uses the concurrent tool path (multiple tool calls and no tool-wrap middleware), execute_tools_concurrently awaits every future with join_all before calling finish_tool_call in call order. Computing duration_ms here therefore measures until fold time, so a fast tool that finished early is reported as running until the slowest sibling completes (and later tools also include earlier after_tool hooks), which corrupts the journal/Langfuse execution window for parallel tools. Capture the completion timestamp/elapsed duration inside each tool future before join_all returns instead.

Useful? React with 👍 / 👎.

let output_bytes = result.content.len() as u64;
let error = result.error.clone();

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P1 Badge Keep tool error text behind payload capture

When RunPolicy::capture.tool_io is false (the default), the PayloadCapture contract says ToolCompleted stays payload-free, but this clones ToolResult::error into the event unconditionally. Since ToolResult::error() duplicates the model-facing tool result content into this field, any failed tool that includes secrets or PII in its error will now be journaled and exported (Langfuse maps it to statusMessage) even though tool input/output capture was disabled; gate the message behind the same capture policy or record only a non-sensitive failure flag.

Useful? React with 👍 / 👎.

let record = ctx.emit(AgentEvent::ToolCompleted {
call_id: prepared.call_id,
tool_name: prepared.tool_name,
started_at_ms: Some(prepared.started_at_ms),
input: prepared.captured_input,
output: captured_output,
duration_ms: Some(duration_ms),
output_bytes: Some(output_bytes),
error,
});
status.set_last_event(record.id);

Expand Down
3 changes: 3 additions & 0 deletions src/harness/events/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -147,6 +147,9 @@ fn completed_events_deserialize_without_started_at_ms() {
started_at_ms: Some(1_704_067_199_000),
input: None,
output: None,
duration_ms: Some(12),
output_bytes: Some(5),
error: None,
};
let json = serde_json::to_value(&event).unwrap();
assert_eq!(json["started_at_ms"], 1_704_067_199_000u64);
Expand Down
16 changes: 16 additions & 0 deletions src/harness/events/types.rs
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,22 @@ pub enum AgentEvent {
/// exporter can render the result in a tool observation's Output panel.
#[serde(default, skip_serializing_if = "Option::is_none")]
output: Option<serde_json::Value>,
/// Wall-clock duration of the call in milliseconds (completion minus
/// [`started_at_ms`]). Present regardless of payload capture, so an
/// exporter renders a real duration without a side-channel. `None` for
/// events serialized before this field existed.
#[serde(default, skip_serializing_if = "Option::is_none")]
duration_ms: Option<u64>,
/// Size, in bytes, of the tool's textual result content. Present even in
/// payload-free mode (unlike [`output`]), so an exporter can show result
/// size without capturing the body. `None` for older events.
#[serde(default, skip_serializing_if = "Option::is_none")]
output_bytes: Option<u64>,
/// Failure message when the tool call failed; `None` on success. Lets an
/// exporter render success/failure and a reason from the journalled
/// event itself rather than a live outcome side-channel.
#[serde(default, skip_serializing_if = "Option::is_none")]
error: Option<String>,
},

/// The model called a tool that is not registered, and the run's
Expand Down
57 changes: 37 additions & 20 deletions src/harness/observability/langfuse/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -316,26 +316,43 @@ fn observation_event(trace_id: &str, obs: &AgentObservation) -> Value {
started_at_ms,
input,
output,
} => json!({
"id": obs.event_id.as_str(),
"timestamp": timestamp,
// A tool call is modelled as a span. `tool-create` is not a valid
// Langfuse ingestion observation type — older/self-hosted Langfuse
// rejects it, silently dropping every tool observation.
"type": "span-create",
"body": clean_nulls(json!({
"id": call_id.as_str(),
"traceId": trace_id,
"name": tool_name,
// Loop-captured start time when available (see the
// generation branch above).
"startTime": started_at_ms.map(iso_ms).unwrap_or_else(|| timestamp.clone()),
"endTime": timestamp,
"input": input,
"output": output,
"metadata": metadata,
})),
}),
duration_ms,
output_bytes,
error,
} => {
// Prefer the loop-captured start + real duration for the end time;
// fall back to the journal timestamp. A failed call is marked ERROR
// with the failure reason, and result size rides metadata so the
// span is informative even in payload-free mode.
let end_time = match (started_at_ms, duration_ms) {
(Some(start), Some(dur)) => iso_ms(start.saturating_add(*dur)),
_ => timestamp.clone(),
};
let mut tool_metadata = metadata.clone();
if let (Some(map), Some(bytes)) = (tool_metadata.as_object_mut(), output_bytes) {
map.insert("output_bytes".into(), json!(bytes));
}
json!({
"id": obs.event_id.as_str(),
"timestamp": timestamp,
// A tool call is modelled as a span. `tool-create` is not a
// valid Langfuse ingestion observation type — older/self-hosted
// Langfuse rejects it, silently dropping every tool observation.
"type": "span-create",
"body": clean_nulls(json!({
"id": call_id.as_str(),
"traceId": trace_id,
"name": tool_name,
"startTime": started_at_ms.map(iso_ms).unwrap_or_else(|| timestamp.clone()),
"endTime": end_time,
"input": input,
"output": output,
"level": error.as_ref().map(|_| "ERROR"),
"statusMessage": error,
"metadata": tool_metadata,
})),
})
}
AgentEvent::RunFailed { error, .. } => json!({
"id": obs.event_id.as_str(),
"timestamp": timestamp,
Expand Down
10 changes: 9 additions & 1 deletion src/harness/observability/langfuse/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -116,6 +116,9 @@ fn populates_generation_and_tool_io_when_captured() {
started_at_ms: Some(1_704_067_199_500),
input: Some(json!({ "query": "weather" })),
output: Some(json!("sunny")),
duration_ms: Some(250),
output_bytes: Some(5),
error: None,
},
),
],
Expand All @@ -135,7 +138,12 @@ fn populates_generation_and_tool_io_when_captured() {
assert_eq!(events[1]["body"]["startTime"], iso_ms(1_704_067_199_000));
assert_eq!(events[1]["body"]["endTime"], iso_ms(1_704_067_200_000));
assert_eq!(events[2]["body"]["startTime"], iso_ms(1_704_067_199_500));
assert_eq!(events[2]["body"]["endTime"], iso_ms(1_704_067_200_001));
// The tool span's end time is now start + the event's own duration_ms
// (1_704_067_199_500 + 250), a real execution window rather than the
// journal-append timestamp.
assert_eq!(events[2]["body"]["endTime"], iso_ms(1_704_067_199_750));
// Result size rides metadata even though this fixture also captured output.
assert_eq!(events[2]["body"]["metadata"]["output_bytes"], 5);

// Observation metadata carries only lineage + event kind, not the whole
// event payload (which would duplicate input/output already in `body`).
Expand Down
3 changes: 3 additions & 0 deletions src/harness/observability/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,9 @@ fn agent_latency_metrics_include_model_tool_and_run_elapsed() {
started_at_ms: None,
input: None,
output: None,
duration_ms: None,
output_bytes: None,
error: None,
},
),
obs(
Expand Down
3 changes: 3 additions & 0 deletions src/harness/testkit/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -341,6 +341,9 @@ fn make_trajectory() -> Vec<AgentEvent> {
started_at_ms: None,
input: None,
output: None,
duration_ms: None,
output_bytes: None,
error: None,
},
AgentEvent::ModelStarted {
call_id: CallId::new("c2"),
Expand Down
3 changes: 3 additions & 0 deletions tests/e2e_orchestrator_subagents.rs
Original file line number Diff line number Diff line change
Expand Up @@ -174,6 +174,9 @@ async fn orchestrator_resolves_and_runs_only_the_chosen_subagents() -> Result<()
started_at_ms: None,
input: None,
output: None,
duration_ms: None,
output_bytes: None,
error: None,
});
Ok::<(String, String), TinyAgentsError>((name, result.content))
}
Expand Down
6 changes: 6 additions & 0 deletions tests/e2e_registry_observability_contracts.rs
Original file line number Diff line number Diff line change
Expand Up @@ -186,6 +186,9 @@ fn component_metadata_and_event_kinds_are_stable_serializable_contracts() {
started_at_ms: None,
input: None,
output: None,
duration_ms: None,
output_bytes: None,
error: None,
},
AgentEvent::StateUpdate,
AgentEvent::MiddlewareStarted { name: "mw".into() },
Expand Down Expand Up @@ -310,6 +313,9 @@ async fn event_sinks_journals_and_status_stores_preserve_run_lineage() {
started_at_ms: None,
input: None,
output: None,
duration_ms: None,
output_bytes: None,
error: None,
});
assert_eq!(journal.len(), 2);
assert_eq!(journal.replay_from(1)[0].event.kind(), "tool.completed");
Expand Down