telemetry: log structured direct tool-call timing

[bolinfest]

Why

App-server deployments can consume structured JSON logs for operational measurements without requiring an OTEL exporter. Existing tool-result telemetry reports the handler outcome, but it does not separate time spent waiting to dispatch from time spent executing the handler.

A compact completion event for the outer, direct tool call lets consumers measure those phases and correlate them with a conversation and turn. Code-mode calls are intentionally excluded so nested runtime calls do not create overlapping events that are easy to double-count.

What changed

• Added a ToolCallTimingGuard around direct tool calls. Event-only strings and timing state are captured only when the codex_core::tools::parallel INFO target is enabled.
• Added a codex.tool_call completion event with conversation, turn, tool, call, trace, dispatch, handler, and total timing fields.
• Recorded the execution-start marker after the dispatch lock is acquired. Event emission snapshots that marker once so a concurrently starting dispatch cannot produce internally inconsistent fields.
• Limited the event to ToolCallSource::Direct; unit coverage verifies code-mode calls are ignored.
• Added cancellation coverage that holds the execution gate and verifies a call cancelled before admission emits exactly one dispatch-only timing event.
• Added reusable JsonLogCapture support, a JSON-logging-specific TestAppServer constructor, and an end-to-end app-server test that drives a direct exec_command through the public v2 JSON-RPC API and validates the emitted JSON event.

Exec-server-specific request and process timing remains in the stacked PR #30901.

Suggested logging filter

LOG_FORMAT=json \
RUST_LOG='warn,codex_core::tools::parallel=info' \
codex app-server

Event example

Identifier and timing values are illustrative.

codex.tool_call

{
  "timestamp": "2026-06-27T03:45:20.443Z",
  "level": "INFO",
  "fields": {
    "message": "tool call completed",
    "event.name": "codex.tool_call",
    "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736",
    "conversation.id": "67e55044-10b1-426f-9247-bb680e5fe0c8",
    "turn_id": "019f04f8-6ac2-78f1-8625-f04a6d35af18",
    "tool_name": "exec_command",
    "call_id": "call_7b8483",
    "tool_source": "direct",
    "execution_started": true,
    "dispatch_duration_ms": 12,
    "handler_duration_ms": 431,
    "total_duration_ms": 443
  },
  "target": "codex_core::tools::parallel"
}

If execution never starts, execution_started is false, handler_duration_ms is 0, and dispatch_duration_ms covers the full observed lifetime.

If a duration cannot be represented as an unsigned 64-bit millisecond value, all three duration fields are omitted rather than populated with a sentinel that could corrupt downstream calculations.

Test plan

• just test -p codex-core tool_call_timing_guard_ignores_code_mode_source
• just test -p codex-core cancellation_before_dispatch_admission_logs_dispatch_only_timing
• just test -p codex-app-server app_server_emits_structured_tool_call_timing_event

---

Stack created with Sapling. Best reviewed with ReviewStack.

• -> telemetry: log structured direct tool-call timing #30334