UAT: JSON/YAML envelope `timing.duration_ms` is always 0 — command execution time not measured #5198

New issue

Open

opened 2026-04-09 03:07:50 +00:00 by HAL9000 · 0 comments

HAL9000 commented

2026-04-09 03:07:50 +00:00

Owner

Bug Report

Feature Area: CLI Commands — JSON/YAML output envelope timing field
Severity: Low — the timing.duration_ms field is always 0; performance monitoring and SLA tracking are broken
Source: src/cleveragents/cli/formatting.py (format_output function)

What Was Tested

Runtime testing of --format json output across multiple commands, examining the timing.duration_ms field.

Expected Behavior (from spec §Output Rendering Framework §json format)

The spec shows timing.duration_ms as the actual elapsed time for the command:

"timing": { "duration_ms": 42 }

The value should reflect the actual wall-clock time taken to execute the command.

Actual Behavior

The timing.duration_ms is always 0 regardless of how long the command took:

"timing": {
  "duration_ms": 0
}

Observed for all tested commands:

agents --format json version → "duration_ms": 0 ❌
agents session list --format json → "duration_ms": 0 ❌
agents project list --format json → "duration_ms": 0 ❌
agents diagnostics --format json → "duration_ms": 0 ❌

Root Cause

In src/cleveragents/cli/formatting.py, the format_output function starts timing with t_start = time.monotonic() but the timing is measured only from the start of format_output itself (which is called at the end of the command), not from the start of the command execution:

def format_output(data, format_type, ...):
    t_start = time.monotonic()
    safe_data = _redact_data(data)
    fmt = format_type.lower()
    
    if fmt in (OutputFormat.JSON.value, ...):
        if fmt == OutputFormat.JSON.value:
            duration_ms = int((time.monotonic() - t_start) * 1000)
            # ↑ This only measures the time to redact + format, not the command execution time

The timer starts when format_output is called (after the command has already executed), so it only measures the serialization time (which is ~0ms).

Steps to Reproduce

agents diagnostics --format json
# Expected: "timing": { "duration_ms": 10 }  (diagnostics takes ~10ms)
# Actual:   "timing": { "duration_ms": 0 }

Impact

Performance monitoring tools that use duration_ms to track command latency receive 0 for all commands
SLA tracking and performance regression detection are impossible
The timing data is meaningless for all commands

Automated by CleverAgents Bot
Supervisor: UAT Testing | Agent: uat-tester

## Bug Report **Feature Area:** CLI Commands — JSON/YAML output envelope `timing` field **Severity:** Low — the `timing.duration_ms` field is always `0`; performance monitoring and SLA tracking are broken **Source:** `src/cleveragents/cli/formatting.py` (`format_output` function) --- ## What Was Tested Runtime testing of `--format json` output across multiple commands, examining the `timing.duration_ms` field. ## Expected Behavior (from spec §Output Rendering Framework §json format) The spec shows `timing.duration_ms` as the actual elapsed time for the command: ```json "timing": { "duration_ms": 42 } ``` The value should reflect the actual wall-clock time taken to execute the command. ## Actual Behavior The `timing.duration_ms` is **always `0`** regardless of how long the command took: ```json "timing": { "duration_ms": 0 } ``` Observed for all tested commands: - `agents --format json version` → `"duration_ms": 0` ❌ - `agents session list --format json` → `"duration_ms": 0` ❌ - `agents project list --format json` → `"duration_ms": 0` ❌ - `agents diagnostics --format json` → `"duration_ms": 0` ❌ ## Root Cause In `src/cleveragents/cli/formatting.py`, the `format_output` function starts timing with `t_start = time.monotonic()` but the timing is measured only from the start of `format_output` itself (which is called at the end of the command), not from the start of the command execution: ```python def format_output(data, format_type, ...): t_start = time.monotonic() safe_data = _redact_data(data) fmt = format_type.lower() if fmt in (OutputFormat.JSON.value, ...): if fmt == OutputFormat.JSON.value: duration_ms = int((time.monotonic() - t_start) * 1000) # ↑ This only measures the time to redact + format, not the command execution time ``` The timer starts when `format_output` is called (after the command has already executed), so it only measures the serialization time (which is ~0ms). ## Steps to Reproduce ```bash agents diagnostics --format json # Expected: "timing": { "duration_ms": 10 } (diagnostics takes ~10ms) # Actual: "timing": { "duration_ms": 0 } ``` ## Impact - Performance monitoring tools that use `duration_ms` to track command latency receive `0` for all commands - SLA tracking and performance regression detection are impossible - The timing data is meaningless for all commands --- **Automated by CleverAgents Bot** Supervisor: UAT Testing | Agent: uat-tester

HAL9000 added the

labels

2026-04-09 03:07:53 +00:00

HAL9000 referenced this issue

2026-04-09 03:08:46 +00:00

[AUTO-UAT-POOL] UAT Testing Report (Cycle 4) #5160

HAL9000 referenced this issue

2026-04-09 03:09:06 +00:00