feat(engine): structured tracing on tool dispatch entry/exit

The tool dispatch path (`Engine::execute_tool_with_lock`) had no
observability around the actual call: we knew when a tool was
*requested* (via the existing engine-loop logs) and when it *audited*
(via `DEEPSEEK_TOOL_AUDIT_LOG` JSONL), but not how long any individual
tool took, what its outcome was, or how the request was routed (MCP
vs in-process registry).

Add two tracing events around every tool call:

* `tool.exec.start` — tool name, dispatch kind (`mcp` / `registry` /
  `missing`), interactive flag, supports-parallel flag, input byte
  size. `tracing::debug!` so the noise is opt-in via
  `RUST_LOG=engine.tool_execution=debug`.

* `tool.exec.end` — same tool/dispatch fields plus `duration_ms`,
  `success` (or `error_kind` mapped from `ToolError` variants), and
  output byte size. Successful calls log at `debug`; failures log at
  `warn` so they surface under the default filter.

Targets are flat strings (`engine.tool_execution`) following the
existing convention already used by `InteractiveTerminalGuard`. CLAUDE.md
documents `RUST_LOG=deepseek_cli::core::engine=debug` as the canonical
filter for agent-loop events; this is the per-tool-call layer beneath
that.
This commit is contained in:
Hunter Bown
2026-05-13 01:47:13 -05:00
parent 7f0773a5d5
commit 8681ea7999
+58 -1
View File
@@ -271,6 +271,27 @@ impl Engine {
mcp_pool: Option<Arc<AsyncMutex<McpPool>>>,
context_override: Option<crate::tools::ToolContext>,
) -> Result<ToolResult, ToolError> {
let started_at = std::time::Instant::now();
let dispatch = if McpPool::is_mcp_tool(&tool_name) {
"mcp"
} else if registry.is_some() {
"registry"
} else {
"missing"
};
let input_bytes = serde_json::to_string(&tool_input)
.map(|s| s.len())
.unwrap_or(0);
tracing::debug!(
target: "engine.tool_execution",
tool = %tool_name,
dispatch,
interactive,
supports_parallel,
input_bytes,
"tool.exec.start",
);
let _guard = if supports_parallel {
ToolExecGuard::Read(lock.read().await)
} else {
@@ -284,7 +305,7 @@ impl Engine {
// cancelled interactive tool).
let _terminal = InteractiveTerminalGuard::engage(tx_event, interactive).await;
if McpPool::is_mcp_tool(&tool_name) {
let outcome = if McpPool::is_mcp_tool(&tool_name) {
if let Some(pool) = mcp_pool {
Engine::execute_mcp_tool_with_pool(pool, &tool_name, tool_input).await
} else {
@@ -300,7 +321,43 @@ impl Engine {
Err(ToolError::not_available(format!(
"tool '{tool_name}' is not registered"
)))
};
let duration_ms = started_at.elapsed().as_millis() as u64;
match &outcome {
Ok(result) => {
tracing::debug!(
target: "engine.tool_execution",
tool = %tool_name,
dispatch,
duration_ms,
success = result.success,
output_bytes = result.content.len(),
"tool.exec.end",
);
}
Err(err) => {
let kind = match err {
ToolError::InvalidInput { .. } => "invalid_input",
ToolError::MissingField { .. } => "missing_field",
ToolError::PathEscape { .. } => "path_escape",
ToolError::ExecutionFailed { .. } => "execution_failed",
ToolError::Timeout { .. } => "timeout",
ToolError::NotAvailable { .. } => "not_available",
ToolError::PermissionDenied { .. } => "permission_denied",
};
tracing::warn!(
target: "engine.tool_execution",
tool = %tool_name,
dispatch,
duration_ms,
error_kind = kind,
error = %err,
"tool.exec.end",
);
}
}
outcome
}
}