Commit Graph

2 Commits

Author SHA1 Message Date
Michael Bolin
beca198b8a telemetry: log structured direct tool-call timing (#30334)
## 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`](141110a73c/codex-rs/core/src/tools/parallel.rs (L32))
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`](141110a73c/codex-rs/core/src/tools/parallel.rs (L313))
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](141110a73c/codex-rs/core/src/tools/parallel.rs (L365))
verifies code-mode calls are ignored.
- Added [cancellation
coverage](141110a73c/codex-rs/core/src/tools/parallel.rs (L408))
that holds the execution gate and verifies a call cancelled before
admission emits exactly one dispatch-only timing event.
- Added reusable
[`JsonLogCapture`](141110a73c/codex-rs/app-server/tests/common/json_logging.rs (L15))
support, a [JSON-logging-specific `TestAppServer`
constructor](141110a73c/codex-rs/app-server/tests/common/test_app_server.rs (L172)),
and an [end-to-end app-server
test](141110a73c/codex-rs/app-server/tests/suite/logging.rs (L52))
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

```bash
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`

```json
{
  "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`

---
[//]: # (BEGIN SAPLING FOOTER)
Stack created with [Sapling](https://sapling-scm.com). Best reviewed
with [ReviewStack](https://reviewstack.dev/openai/codex/pull/30334).
* __->__ #30334
2026-07-02 13:53:56 -07:00
Michael Bolin
4f1b5a4b73 app-server: structure and test JSON shutdown logs (#30314)
## Why

`LOG_FORMAT=json` and `RUST_LOG` are supported by app-server, but the
behavior was only covered indirectly. We should verify the actual JSONL
written by both user-facing entry points: `codex app-server` and the
standalone `codex-app-server` binary.

The existing processor shutdown message also always said the channel
closed, even though the processor can exit for several different
reasons. Structured fields make that event more accurate and useful to
log consumers.

## What changed

- Record the processor `exit_reason`, remaining connection count, and
forced-shutdown state as structured tracing fields.
- Add a shared process-test helper that enables JSON logging, validates
every stderr line as JSON, and verifies the top-level timestamp is RFC
3339.
- Cover both `codex app-server` and `codex-app-server`, asserting the
stable `level`, `fields`, and `target` payload.

## Test plan

- `just test -p codex-app-server
standalone_app_server_emits_json_info_events`
- `just test -p codex-cli app_server_emits_json_info_events`
2026-06-26 18:19:56 -07:00