diff --git a/README.md b/README.md index 31b4eb0..f1cfc3a 100644 --- a/README.md +++ b/README.md @@ -159,21 +159,30 @@ Inspect a completed or interrupted run without manually scanning JSONL: ```bash uv run yada-trace \ - .yada/runs/fix-parser-edge-case__2026-08-02_12-26-26.123456Z.jsonl + .yada/runs/fix-parser-edge-case__2026-08-02_20-26.jsonl uv run yada-trace \ - eval-results/pytest-dev__pytest-10051__2026-08-02_12-26-26.123456Z.artifacts/yada-trace.jsonl \ + eval-results/pytest-dev__pytest-10051__2026-08-02_20-26.artifacts/yada-trace.jsonl \ --step 8 -uv run yada-trace eval-results/__.artifacts/yada-trace.jsonl \ +uv run yada-trace eval-results/__.artifacts/yada-trace.jsonl \ --verbose +uv run yada-trace TRACE.jsonl --events ``` -The report correlates model requests, tool-call IDs, errors, reminders, and the -final verification state into a compact timeline. `--step` and `--verbose` -expand sanitized model messages, tool arguments, patches, stdout, and stderr. -The source JSONL remains the durable, streaming-friendly record. Debug traces can -contain source code and test output even after secret redaction, so handle them as -sensitive artifacts. See [docs/tracing.md](docs/tracing.md) for the event -reference, field-presence semantics, lifecycle, and `jq` recipes. +The default report groups each model request, response, planning decision, and +ordered tool executions into one agent step. Every summary includes physical +JSONL line references so the source evidence is immediately reachable with tools +such as `sed`. `--step` and `--verbose` expand sanitized model messages, tool +arguments, patches, stdout, and stderr inside grouped steps; `--events` retains a +line-prefixed flat timeline. The source JSONL remains the durable, +streaming-friendly record. Debug traces can contain source code and test output +even after secret redaction, so handle them as sensitive artifacts. See +[docs/tracing.md](docs/tracing.md) for the event reference, field-presence +semantics, lifecycle, and `jq` recipes. + +Default trace and evaluation paths use the system-local time at minute +precision. If a name already exists, Yada appends `(1)`, `(2)`, and so on before +the file or artifacts suffix, keeping the result JSON and artifacts directory on +the same number. ## Safety model diff --git a/README.zh-CN.md b/README.zh-CN.md index 868b395..bbbea0c 100644 --- a/README.zh-CN.md +++ b/README.zh-CN.md @@ -119,11 +119,18 @@ uv run yada eval \ uv run yada-trace .yada/runs/20260801T120000.000000Z.jsonl uv run yada-trace eval-results/.artifacts/yada-trace.jsonl --step 8 uv run yada-trace eval-results/.artifacts/yada-trace.jsonl --verbose +uv run yada-trace TRACE.jsonl --events ``` -报告会汇总模型轮次、工具调用 ID、失败、协议提醒和最终验证状态。 -`--step` 和 `--verbose` 会展开脱敏后的模型消息、工具参数、Patch、stdout 和 -stderr。Debug trace 脱敏后仍可能包含源码和测试输出，应当作敏感 artifact 处理。 +默认报告会按 Agent step 归组模型请求、响应、规划决定和有序工具执行，并为 +step、模型调用、工具执行和协议事件显示真实 JSONL 行号。`--step` 和 +`--verbose` 会在分组内展开脱敏后的模型消息、工具参数、Patch、stdout 和 +stderr；`--events` 可切回带物理行号的平铺时间线。Debug trace 脱敏后仍可能 +包含源码和测试输出，应当作敏感 artifact 处理。 + +默认 trace 和评测路径使用精确到分钟的系统本地时间，不包含秒和小数秒。 +若名称已存在，Yada 会在文件或 `.artifacts` 后缀前依次添加 `(1)`、`(2)`； +同一次评测的结果 JSON 与 artifacts 目录始终使用相同编号。 ## 安全边界 diff --git a/docs/architecture.md b/docs/architecture.md index 31bcf9a..ee215a6 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -96,12 +96,13 @@ results remain correlated by step, request ID, and tool-call ID. `run_start` records Yada version/commit, workspace base commit, case ID when available, and the model configuration. -`yada-trace PATH` renders the compact summary. `--step N` expands one request → -response → tools slice, while `--verbose` expands the full timeline. Reasoning -is length/hash-redacted in summary traces and automatically retained in debug -traces. Common secret keys and bearer/API-key-like text are redacted in both -modes. A debug trace can still contain reasoning, source code, and test output -and must be handled as a sensitive artifact. +`yada-trace PATH` renders one source-located section per agent step. `--step N` +expands one complete request → response → tools step, while `--verbose` expands +every grouped step and `--events` provides the line-prefixed flat timeline. +Reasoning is length/hash-redacted in summary traces and automatically retained in +debug traces. Common secret keys and bearer/API-key-like text are redacted in +both modes. A debug trace can still contain reasoning, source code, and test +output and must be handled as a sensitive artifact. The complete event and field reference lives in [tracing.md](tracing.md). The MVP stores a full sanitized request snapshot per turn. This deliberately diff --git a/docs/tracing.md b/docs/tracing.md index 736c938..301975b 100644 --- a/docs/tracing.md +++ b/docs/tracing.md @@ -44,6 +44,13 @@ run_end - A transport exception or process interruption can leave a trace without `run_end`. Readers should report this as interrupted, not successful. +The reporting layer normalizes these records into `TraceRun`, `TraceStep`, +`TraceToolExecution`, and `LocatedTraceEvent` objects. A located event pairs the +unchanged persisted record with its physical JSONL line number. The public +`read_trace()` API still returns the original event dictionaries; source location +metadata is available through `read_located_trace()` and is never written back to +JSONL. + ## Core events | Event | Cardinality and meaning | Important `data` fields | @@ -97,12 +104,14 @@ output. ## Inspection recipes -Default paths include a sanitized task name and a readable UTC timestamp. A -direct run resembles -`.yada/runs/fix-parser-boundary-issue__2026-08-02_12-26-26.123456Z.jsonl`. -An evaluation stores its trace under a directory such as -`eval-results/pytest-dev__pytest-10051__2026-08-02_12-26-26.123456Z.artifacts/`. -Explicit `--trace`, `--output`, and `--artifact-dir` values are never renamed. +Default paths include a sanitized task name and the system-local time at minute +precision. A direct run resembles +`.yada/runs/fix-parser-boundary-issue__2026-08-02_20-26.jsonl`. An evaluation +stores its trace under a directory such as +`eval-results/pytest-dev__pytest-10051__2026-08-02_20-26.artifacts/`. When a +default name already exists, Yada adds `(1)`, `(2)`, and so on before the output +suffix. The result JSON and artifacts directory share the same number. Explicit +`--trace`, `--output`, and `--artifact-dir` values are never renamed. Render a run summary or expand one step: @@ -110,6 +119,23 @@ Render a run summary or expand one step: uv run yada-trace TRACE.jsonl uv run yada-trace TRACE.jsonl --step 12 uv run yada-trace TRACE.jsonl --verbose +uv run yada-trace TRACE.jsonl --events +``` + +The default view groups events by agent step. Step headings show the complete +physical line range, model calls identify their request and response lines, and +tool executions identify their call and result lines. Protocol reminders and +violations also carry line references. Blank JSONL lines still count as physical +lines, while `sequence` remains the deterministic event-order field; the two are +not interchangeable. `--events` keeps the previous flat timeline shape and +prefixes every event with its physical line. + +Once a report identifies a suspicious step or tool execution, inspect the exact +source records directly: + +```bash +sed -n '31p' TRACE.jsonl +sed -n '33,34p' TRACE.jsonl ``` List event counts: diff --git a/src/yada/evals/cli.py b/src/yada/evals/cli.py index 3b565f1..d8a2fab 100644 --- a/src/yada/evals/cli.py +++ b/src/yada/evals/cli.py @@ -12,7 +12,7 @@ from yada.evals.base import RunBudget from yada.evals.benchmarks import LocalBenchmark, SWEbenchBenchmark from yada.evals.runner import EvalRunner -from yada.utils.naming import readable_run_name +from yada.utils.naming import next_available_run_name, readable_run_name def build_parser() -> argparse.ArgumentParser: @@ -45,7 +45,7 @@ def build_parser() -> argparse.ArgumentParser: "--output", type=Path, help=( - "Result JSON path (default: eval-results/__.json)." + "Result JSON path (default: eval-results/__.json)." ), ) parser.add_argument( @@ -242,7 +242,13 @@ def run_cli(argv: list[str] | None = None) -> int: def _default_output_path(task_name: str) -> Path: - return Path("eval-results") / f"{readable_run_name(task_name)}.json" + directory = Path("eval-results") + run_name = next_available_run_name( + directory, + readable_run_name(task_name), + suffixes=(".json", ".artifacts"), + ) + return directory / f"{run_name}.json" def _manifest_instance_id(benchmark: LocalBenchmark) -> str: diff --git a/src/yada/run/cli.py b/src/yada/run/cli.py index 66ab2f3..90b79ac 100644 --- a/src/yada/run/cli.py +++ b/src/yada/run/cli.py @@ -12,7 +12,7 @@ from yada.models import DeepSeekAPIError, DeepSeekClient from yada.tools import ToolRunner from yada.traces import TraceWriter -from yada.utils.naming import readable_run_name +from yada.utils.naming import next_available_run_name, readable_run_name def build_parser() -> argparse.ArgumentParser: @@ -67,7 +67,7 @@ def build_parser() -> argparse.ArgumentParser: type=Path, help=( "JSONL trace path (default: " - "WORKSPACE/.yada/runs/__.jsonl)." + "WORKSPACE/.yada/runs/__.jsonl)." ), ) parser.add_argument( @@ -183,7 +183,13 @@ def run_cli(argv: list[str] | None = None) -> int: def _default_trace_path(workspace: Path, task: str) -> Path: - return workspace / ".yada" / "runs" / f"{readable_run_name(task)}.jsonl" + directory = workspace / ".yada" / "runs" + run_name = next_available_run_name( + directory, + readable_run_name(task), + suffixes=(".jsonl",), + ) + return directory / f"{run_name}.jsonl" def main() -> None: diff --git a/src/yada/traces/__init__.py b/src/yada/traces/__init__.py index 5d8e455..0889a2f 100644 --- a/src/yada/traces/__init__.py +++ b/src/yada/traces/__init__.py @@ -2,7 +2,13 @@ from yada.traces.jsonl import TRACE_LEVELS, TRACE_SCHEMA_VERSION, TraceWriter from yada.traces.report import ( + LocatedTraceEvent, TraceFormatError, + TraceRun, + TraceStep, + TraceToolExecution, + build_trace_run, + read_located_trace, read_trace, reconstruct_model_request, render_trace_report, @@ -11,8 +17,14 @@ __all__ = [ "TRACE_LEVELS", "TRACE_SCHEMA_VERSION", + "LocatedTraceEvent", + "TraceRun", + "TraceStep", "TraceFormatError", + "TraceToolExecution", "TraceWriter", + "build_trace_run", + "read_located_trace", "read_trace", "reconstruct_model_request", "render_trace_report", diff --git a/src/yada/traces/cli.py b/src/yada/traces/cli.py index 9a89424..d1d1a9b 100644 --- a/src/yada/traces/cli.py +++ b/src/yada/traces/cli.py @@ -14,7 +14,7 @@ def build_parser() -> argparse.ArgumentParser: parser = argparse.ArgumentParser( prog="yada-trace", - description="Summarize a Yada JSONL run as a correlated timeline.", + description="Summarize a Yada JSONL run as correlated agent steps.", ) parser.add_argument("trace", type=Path, help="Path to a Yada JSONL trace.") parser.add_argument( @@ -25,7 +25,12 @@ def build_parser() -> argparse.ArgumentParser: parser.add_argument( "--verbose", action="store_true", - help="Expand event payloads for the complete timeline.", + help="Expand event payloads inside every grouped step.", + ) + parser.add_argument( + "--events", + action="store_true", + help="Show the legacy flat event timeline with physical line numbers.", ) return parser @@ -39,6 +44,7 @@ def run_cli(argv: list[str] | None = None) -> int: args.trace.expanduser().resolve(), step=args.step, verbose=args.verbose, + events=args.events, ) except (OSError, TraceFormatError) as exc: print(f"yada-trace: {exc}", file=sys.stderr) diff --git a/src/yada/traces/report.py b/src/yada/traces/report.py index 3a547ac..e503f58 100644 --- a/src/yada/traces/report.py +++ b/src/yada/traces/report.py @@ -1,10 +1,11 @@ -"""Human-readable diagnostics derived from Yada JSONL traces.""" +"""Step-oriented diagnostics derived from Yada JSONL traces.""" from __future__ import annotations import json +from dataclasses import dataclass from pathlib import Path -from typing import Any +from typing import Any, Iterable from yada.traces.jsonl import TRACE_SCHEMA_VERSION @@ -13,22 +14,74 @@ class TraceFormatError(ValueError): """Raised when a JSONL trace contains an invalid event record.""" -def read_trace(path: Path) -> list[dict[str, Any]]: - """Load and minimally validate all events in a trace file. +@dataclass(frozen=True) +class LocatedTraceEvent: + """One trace event paired with its physical JSONL source line.""" + + line_number: int + record: dict[str, Any] + + @property + def name(self) -> str: + """Return the event type.""" + + return self.record["event"] + + @property + def data(self) -> dict[str, Any]: + """Return the event-specific payload.""" + + return self.record["data"] + + +@dataclass(frozen=True) +class TraceToolExecution: + """A tool call and its correlated result, either of which may be missing.""" + + call: LocatedTraceEvent | None + result: LocatedTraceEvent | None + + +@dataclass(frozen=True) +class TraceStep: + """All located events that belong to one agent-loop step.""" + + number: int + events: tuple[LocatedTraceEvent, ...] + model_request: LocatedTraceEvent | None + model_response: LocatedTraceEvent | None + plan_decision: LocatedTraceEvent | None + protocol_events: tuple[LocatedTraceEvent, ...] + tool_executions: tuple[TraceToolExecution, ...] + + @property + def first_line(self) -> int: + """Return the first physical source line occupied by this step.""" + + return min(event.line_number for event in self.events) + + @property + def last_line(self) -> int: + """Return the last physical source line occupied by this step.""" - Args: - path: UTF-8 JSONL trace generated by :class:`TraceWriter`. + return max(event.line_number for event in self.events) - Returns: - Event dictionaries in file order. Legacy records without correlation - metadata are accepted so older runs remain inspectable. - Raises: - TraceFormatError: If a non-empty line is not a valid event object. - OSError: If the trace cannot be read. - """ +@dataclass(frozen=True) +class TraceRun: + """Normalized, source-located reporting model for one trace run.""" - events: list[dict[str, Any]] = [] + events: tuple[LocatedTraceEvent, ...] + run_start: LocatedTraceEvent | None + steps: tuple[TraceStep, ...] + run_end: LocatedTraceEvent | None + ungrouped_events: tuple[LocatedTraceEvent, ...] + + +def read_located_trace(path: Path) -> list[LocatedTraceEvent]: + """Load trace events while retaining their physical JSONL line numbers.""" + + events: list[LocatedTraceEvent] = [] lines = path.read_text(encoding="utf-8").splitlines() for line_number, line in enumerate(lines, 1): if not line.strip(): @@ -51,21 +104,67 @@ def read_trace(path: Path) -> list[dict[str, Any]]: f"line {line_number}: trace schema {schema_version} is newer than " f"supported schema {TRACE_SCHEMA_VERSION}" ) - events.append(record) + events.append(LocatedTraceEvent(line_number, record)) if not events: raise TraceFormatError("trace contains no events") return events +def read_trace(path: Path) -> list[dict[str, Any]]: + """Load trace records in file order without changing the public API.""" + + return [event.record for event in read_located_trace(path)] + + +def build_trace_run(events: Iterable[LocatedTraceEvent]) -> TraceRun: + """Correlate located events into a reusable step-oriented reporting model.""" + + located = tuple(sorted(events, key=_event_order)) + if not located: + raise TraceFormatError("trace contains no events") + + request_steps: dict[str, int] = {} + tool_steps: dict[str, int] = {} + for event in located: + step = _step_number(event.data.get("step")) + if step is None: + continue + request_id = event.data.get("request_id") + tool_call_id = event.data.get("tool_call_id") + if request_id is not None: + request_steps[str(request_id)] = step + if tool_call_id is not None: + tool_steps[str(tool_call_id)] = step + + step_events: dict[int, list[LocatedTraceEvent]] = {} + ungrouped: list[LocatedTraceEvent] = [] + for event in located: + step = _step_number(event.data.get("step")) + if step is None and event.data.get("request_id") is not None: + step = request_steps.get(str(event.data["request_id"])) + if step is None and event.data.get("tool_call_id") is not None: + step = tool_steps.get(str(event.data["tool_call_id"])) + if step is None: + ungrouped.append(event) + else: + step_events.setdefault(step, []).append(event) + + steps = tuple( + _build_step(number, tuple(group)) + for number, group in sorted(step_events.items()) + ) + run_start = next((event for event in located if event.name == "run_start"), None) + run_end = next( + (event for event in reversed(located) if event.name == "run_end"), None + ) + return TraceRun(located, run_start, steps, run_end, tuple(ungrouped)) + + def reconstruct_model_request( events: list[dict[str, Any]], step: int, ) -> dict[str, Any]: - """Return the sanitized provider payload captured for one model turn. - - Summary and legacy traces intentionally lack this payload. Callers receive a - clear error instead of a partial reconstruction assembled from source code. - """ + """Return the sanitized provider payload captured for one model turn.""" request = next( ( @@ -90,60 +189,160 @@ def render_trace_report( *, step: int | None = None, verbose: bool = False, + events: bool = False, ) -> str: - """Render a compact run summary and chronological event timeline. + """Render a grouped report, or an explicitly requested flat event timeline.""" - The report intentionally summarizes large prompts, arguments, and command - output instead of echoing them. The original JSONL remains available when a - specific payload needs deeper inspection. + run = build_trace_run(read_located_trace(path)) + selected_steps = run.steps + if step is not None: + selected_steps = tuple(item for item in run.steps if item.number == step) + if not selected_steps: + raise TraceFormatError(f"trace contains no events for step {step}") - Args: - path: Trace file to inspect. + lines = _report_header(path, run) + if events: + lines.extend(_render_flat_events(run, step=step, verbose=verbose)) + else: + max_steps = _maximum_steps(run) + for item in selected_steps: + lines.extend( + _render_step(item, run, max_steps, expanded=verbose or step is not None) + ) + return "\n".join(lines) + "\n" - Returns: - Plain text suitable for a terminal, issue, or interview walkthrough. - """ - events = read_trace(path) - timeline_events = events - if step is not None: - timeline_events = [ - event for event in events if event["data"].get("step") == step - ] - if not timeline_events: - raise TraceFormatError(f"trace contains no events for step {step}") - start = _first_event(events, "run_start") - end = _first_event(reversed(events), "run_end") - model_turns = sum(event["event"] == "assistant" for event in events) - tool_results = [event for event in events if event["event"] == "tool_result"] - tool_failures = sum( - not bool(event["data"].get("result", {}).get("ok")) for event in tool_results +def _build_step(number: int, events: tuple[LocatedTraceEvent, ...]) -> TraceStep: + ordered = tuple(sorted(events, key=_event_order)) + requests = [event for event in ordered if event.name == "model_request"] + responses = [ + event for event in ordered if event.name in {"assistant", "model_error"} + ] + request = requests[0] if requests else None + response = _matching_response(request, responses) + plan = next((event for event in ordered if event.name == "plan_decision"), None) + protocol = tuple( + event + for event in ordered + if event.name in {"protocol_reminder", "protocol_violation"} ) - reminders = sum(event["event"] == "protocol_reminder" for event in events) - last_elapsed = max( - ( - event.get("elapsed_ms", 0) - for event in events - if isinstance(event.get("elapsed_ms"), int) - ), - default=0, + tools = _pair_tools(ordered) + return TraceStep(number, ordered, request, response, plan, protocol, tools) + + +def _matching_response( + request: LocatedTraceEvent | None, + responses: list[LocatedTraceEvent], +) -> LocatedTraceEvent | None: + if not responses: + return None + if request is not None and request.data.get("request_id") is not None: + request_id = str(request.data["request_id"]) + match = next( + ( + response + for response in responses + if response.data.get("request_id") is not None + and str(response.data["request_id"]) == request_id + ), + None, + ) + if match is not None: + return match + return next( + ( + response + for response in responses + if response.data.get("request_id") is None + ), + None, + ) + return responses[0] + + +def _pair_tools( + events: tuple[LocatedTraceEvent, ...], +) -> tuple[TraceToolExecution, ...]: + calls = [event for event in events if event.name == "tool_call"] + results = [event for event in events if event.name == "tool_result"] + used_results: set[int] = set() + executions: list[TraceToolExecution] = [] + for call in calls: + call_id = call.data.get("tool_call_id") + result_index = next( + ( + index + for index, result in enumerate(results) + if index not in used_results + and call_id is not None + and result.data.get("tool_call_id") is not None + and str(result.data["tool_call_id"]) == str(call_id) + ), + None, + ) + if result_index is None and call_id is None: + legacy_matches = [ + index + for index, result in enumerate(results) + if index not in used_results + and result.data.get("tool") == call.data.get("tool") + ] + result_index = legacy_matches[0] if len(legacy_matches) == 1 else None + elif result_index is None: + legacy_matches = [ + index + for index, result in enumerate(results) + if index not in used_results + and result.data.get("tool_call_id") is None + and result.data.get("tool") == call.data.get("tool") + ] + result_index = legacy_matches[0] if len(legacy_matches) == 1 else None + result = results[result_index] if result_index is not None else None + if result_index is not None: + used_results.add(result_index) + executions.append(TraceToolExecution(call, result)) + executions.extend( + TraceToolExecution(None, result) + for index, result in enumerate(results) + if index not in used_results ) + return tuple(executions) - start_data = start["data"] if start else {} - end_data = end["data"] if end else {} + +def _report_header(path: Path, run: TraceRun) -> list[str]: + start_data = run.run_start.data if run.run_start else {} run_id = next( - (event.get("run_id") for event in events if event.get("run_id")), + ( + event.record.get("run_id") + for event in run.events + if event.record.get("run_id") + ), "legacy", ) - outcome = ( - "finished" - if end_data.get("finished") is True - else "unfinished" - if end - else "interrupted (no run_end event)" + model_turns = sum(event.name == "assistant" for event in run.events) + tool_results = [event for event in run.events if event.name == "tool_result"] + tool_errors = sum( + _tool_result_payload(event).get("ok") is not True for event in tool_results + ) + nonzero_commands = sum( + isinstance(_tool_result_payload(event).get("exit_code"), int) + and _tool_result_payload(event)["exit_code"] != 0 + for event in tool_results + ) + reminders = sum(event.name == "protocol_reminder" for event in run.events) + last_elapsed = max( + ( + event.record.get("elapsed_ms", 0) + for event in run.events + if isinstance(event.record.get("elapsed_ms"), int) + ), + default=0, ) - lines = [ + observed_steps = max((step.number for step in run.steps), default=0) + outcome = _outcome_text(run.run_end, observed_steps) + return [ "Yada trace report", + "", f"Path: {path}", f"Run: {run_id}", f"Model: {start_data.get('model', 'unknown')}", @@ -153,33 +352,258 @@ def render_trace_report( ( "Totals: " f"{model_turns} model turns, {len(tool_results)} tool results, " - f"{tool_failures} tool failures, {reminders} reminders, {last_elapsed} ms" + f"{tool_errors} tool errors, {nonzero_commands} non-zero commands, " + f"{reminders} reminders, {last_elapsed} ms" ), - f"Timeline{f' (step {step})' if step is not None else ''}:", + "", ] - detailed = verbose or step is not None - for fallback_sequence, event in enumerate(timeline_events, 1): - sequence = event.get("sequence", fallback_sequence) - elapsed = event.get("elapsed_ms", "?") - lines.append(f" [{sequence!s:>3} +{elapsed!s:>6}ms] {_describe_event(event)}") - if detailed: - if event["event"] == "model_request" and "payload" not in event["data"]: - lines.append( - " payload unavailable: rerun with --trace-level debug" - ) + + +def _outcome_text(run_end: LocatedTraceEvent | None, observed_steps: int) -> str: + if run_end is None: + return "interrupted (no run_end event)" + steps = _step_number(run_end.data.get("steps")) or observed_steps + suffix = f" in {steps} {_plural(steps, 'step')}" if steps else "" + if run_end.data.get("finished") is True: + return f"resolved{suffix}" + return ( + f"unfinished after {steps} {_plural(steps, 'step')}" if steps else "unfinished" + ) + + +def _render_step( + step: TraceStep, + run: TraceRun, + max_steps: int, + *, + expanded: bool, +) -> list[str]: + response = step.model_response + start_data = run.run_start.data if run.run_start else {} + model = ( + response.data.get("model") + if response is not None and response.name == "assistant" + else None + ) or start_data.get("model", "unknown") + label = "interrupted" if step.model_request and response is None else str(model) + heading = f"Step {step.number}/{max_steps} — {label}" + if response is not None and isinstance( + response.data.get("duration_ms"), (int, float) + ): + heading += f" {_duration(response.data['duration_ms'])}" + tokens = _total_tokens(response.data.get("usage")) if response else None + if tokens is not None: + heading += f" {tokens:,} tokens" + heading += f" {_line_range(step.first_line, step.last_line)}" + lines = [heading] + + if step.model_request is not None or response is not None: + response_label = ( + "error" if response and response.name == "model_error" else "response" + ) + lines.append( + " Model call " + + _pair_reference("request", step.model_request, response_label, response) + ) + if response is not None and response.name == "assistant": + lines.append( + f" Finish reason: {response.data.get('finish_reason', '?')}" + ) + reasoning_chars = _reasoning_length(response.data.get("message")) + if reasoning_chars is not None: + lines.append(f" Reasoning: {reasoning_chars:,} chars") + elif response is not None: + error_type = response.data.get("error_type", "Error") + error = _one_line(response.data.get("error", ""), 160) + lines.append(f" Error: {error_type}: {error}") + + if step.plan_decision is not None: + plan = step.plan_decision + lines.append( + f" Plan: {plan.data.get('action', '?')} {_event_reference(plan)}" + ) + if plan.data.get("rejection_error"): + lines.append( + " Rejected: " + _one_line(plan.data["rejection_error"], 160) + ) + + for protocol in step.protocol_events: + label = "Reminder" if protocol.name == "protocol_reminder" else "Violation" + detail = protocol.data.get("text") or protocol.data.get("error") or "" + lines.append( + f" Protocol {label.lower()}: {_one_line(detail, 160)} " + f"{_event_reference(protocol)}" + ) + + if step.tool_executions: + lines.append(" Tools:") + for execution in step.tool_executions: + lines.append(" " + _tool_summary(execution)) + + if expanded: + lines.extend(_expanded_step_events(step.events)) + lines.append("") + return lines + + +def _tool_summary(execution: TraceToolExecution) -> str: + source = execution.call or execution.result + if source is None: + return "[missing] unknown [call missing → result missing]" + name = source.data.get("tool", "?") + result_data = execution.result.data if execution.result else {} + result = result_data.get("result") if execution.result else None + if not isinstance(result, dict): + status = "missing" if execution.result is None else "error" + result = {} + else: + status = "ok" if result.get("ok") is True else "error" + parts = [f"[{status}] {name}"] + duration = result_data.get("duration_ms") + if isinstance(duration, (int, float)): + parts.append(_duration(duration)) + if "exit_code" in result: + parts.append(f"exit={result.get('exit_code')}") + parts.append(_pair_reference("call", execution.call, "result", execution.result)) + return " ".join(parts) + + +def _expanded_step_events(events: tuple[LocatedTraceEvent, ...]) -> list[str]: + lines = ["", " Events:"] + for event in events: + sequence = event.record.get("sequence") + sequence_text = f" sequence={sequence}" if isinstance(sequence, int) else "" + lines.append(f" L{event.line_number} {event.name}{sequence_text}") + if event.name == "model_request" and "payload" not in event.data: + lines.append(" payload unavailable: rerun with --trace-level debug") + rendered = json.dumps( + event.data, + ensure_ascii=False, + indent=2, + sort_keys=True, + default=str, + ) + lines.extend(f" {line}" for line in rendered.splitlines()) + return lines + + +def _render_flat_events( + run: TraceRun, + *, + step: int | None, + verbose: bool, +) -> list[str]: + selected = run.events + if step is not None: + selected_lines = { + event.line_number + for trace_step in run.steps + if trace_step.number == step + for event in trace_step.events + } + selected = tuple( + event for event in run.events if event.line_number in selected_lines + ) + lines = [f"Events{f' (step {step})' if step is not None else ''}:"] + for fallback_sequence, event in enumerate(selected, 1): + sequence = event.record.get("sequence", fallback_sequence) + elapsed = event.record.get("elapsed_ms", "?") + lines.append( + f" L{event.line_number} [{sequence!s:>3} +{elapsed!s:>6}ms] " + f"{_describe_event(event.record)}" + ) + if verbose: rendered = json.dumps( - event["data"], + event.data, ensure_ascii=False, indent=2, sort_keys=True, default=str, ) lines.extend(f" {line}" for line in rendered.splitlines()) - return "\n".join(lines) + "\n" + return lines -def _first_event(events, name: str) -> dict[str, Any] | None: - return next((event for event in events if event["event"] == name), None) +def _maximum_steps(run: TraceRun) -> int: + start_max = run.run_start.data.get("max_steps") if run.run_start else None + observed = max((step.number for step in run.steps), default=0) + if isinstance(start_max, int) and start_max > 0: + return max(start_max, observed) + end_steps = run.run_end.data.get("steps") if run.run_end else None + if isinstance(end_steps, int) and end_steps > 0: + return max(end_steps, observed) + return observed + + +def _event_order(event: LocatedTraceEvent) -> tuple[int, int]: + sequence = event.record.get("sequence") + return ( + sequence if isinstance(sequence, int) else event.line_number, + event.line_number, + ) + + +def _step_number(value: Any) -> int | None: + return value if isinstance(value, int) and value > 0 else None + + +def _event_reference(event: LocatedTraceEvent) -> str: + return f"[L{event.line_number}]" + + +def _line_range(first: int, last: int) -> str: + return f"[L{first}]" if first == last else f"[L{first}–L{last}]" + + +def _pair_reference( + first_label: str, + first: LocatedTraceEvent | None, + second_label: str, + second: LocatedTraceEvent | None, +) -> str: + first_location = f"L{first.line_number}" if first else "missing" + second_location = f"L{second.line_number}" if second else "missing" + return f"[{first_label} {first_location} → {second_label} {second_location}]" + + +def _duration(milliseconds: int | float) -> str: + if milliseconds < 1000: + return f"{milliseconds:g}ms" + seconds = milliseconds / 1000 + return f"{seconds:.1f}s" if seconds < 10 else f"{seconds:g}s" + + +def _total_tokens(usage: Any) -> int | None: + if not isinstance(usage, dict): + return None + total = usage.get("total_tokens") + if isinstance(total, int): + return total + prompt = usage.get("prompt_tokens") + completion = usage.get("completion_tokens") + if isinstance(prompt, int) and isinstance(completion, int): + return prompt + completion + return None + + +def _reasoning_length(message: Any) -> int | None: + if not isinstance(message, dict) or "reasoning_content" not in message: + return None + reasoning = message["reasoning_content"] + if isinstance(reasoning, dict) and isinstance(reasoning.get("chars"), int): + return reasoning["chars"] + if isinstance(reasoning, str): + return len(reasoning) + return 0 if reasoning is None else len(str(reasoning)) + + +def _tool_result_payload(event: LocatedTraceEvent) -> dict[str, Any]: + result = event.data.get("result") + return result if isinstance(result, dict) else {} + + +def _plural(count: int, word: str) -> str: + return word if count == 1 else f"{word}s" def _describe_event(event: dict[str, Any]) -> str: @@ -216,40 +640,17 @@ def _describe_event(event: dict[str, Any]) -> str: ) if name == "plan_decision": tools = ",".join(str(tool) for tool in (data.get("tools") or [])) - detail = "" - if data.get("rejection_error"): - detail = f" rejected={_one_line(data['rejection_error'], 100)}" return ( f"{step_text}plan_decision action={data.get('action', '?')} " - f"tools={tools or '-'}{detail}" - ) - if name == "tool_call": - arguments = data.get("arguments") - if data.get("rejected"): - keys = "rejected" - else: - keys = ",".join(sorted(arguments)) if isinstance(arguments, dict) else "raw" - return ( - f"{step_text}tool_call id={data.get('tool_call_id', '?')} " - f"tool={data.get('tool', '?')} args={keys or '-'}" + f"tools={tools or '-'}" ) - if name == "tool_result": - result = data.get("result") or {} - status = "ok" if result.get("ok") else "error" - detail = "" - if not result.get("ok"): - detail = f" detail={_one_line(result.get('error', 'unknown error'), 120)}" - elif "exit_code" in result: - detail = f" exit={result.get('exit_code')}" + if name in {"tool_call", "tool_result"}: return ( - f"{step_text}tool_result id={data.get('tool_call_id', '?')} " - f"tool={data.get('tool', '?')} status={status} " - f"duration={data.get('duration_ms', '?')}ms{detail}" + f"{step_text}{name} id={data.get('tool_call_id', '?')} " + f"tool={data.get('tool', '?')}" ) - if name == "protocol_reminder": - return f"{step_text}protocol_reminder" - if name == "protocol_violation": - return f"{step_text}protocol_violation {_one_line(data.get('error', ''), 120)}" + if name in {"protocol_reminder", "protocol_violation"}: + return f"{step_text}{name}" if name == "run_end": return ( f"run_end finished={data.get('finished')} steps={data.get('steps')} " diff --git a/src/yada/utils/naming.py b/src/yada/utils/naming.py index 4e24bcf..c3fa5c3 100644 --- a/src/yada/utils/naming.py +++ b/src/yada/utils/naming.py @@ -4,7 +4,8 @@ import re import unicodedata -from datetime import datetime, timezone +from datetime import datetime +from pathlib import Path _WINDOWS_RESERVED_NAMES = { "aux", @@ -34,10 +35,33 @@ def task_slug(task: str, *, max_length: int = 48) -> str: def readable_run_name(task: str, *, now: datetime | None = None) -> str: - """Combine a task slug with a sortable, readable UTC timestamp.""" + """Combine a task slug with the system-local time at minute precision.""" - instant = now or datetime.now(timezone.utc) - if instant.tzinfo is None: - instant = instant.replace(tzinfo=timezone.utc) - timestamp = instant.astimezone(timezone.utc).strftime("%Y-%m-%d_%H-%M-%S.%fZ") + instant = now or datetime.now().astimezone() + timestamp = instant.strftime("%Y-%m-%d_%H-%M") return f"{task_slug(task)}__{timestamp}" + + +def next_available_run_name( + directory: Path, + base_name: str, + *, + suffixes: tuple[str, ...], +) -> str: + """Return a run name unused by every related output suffix. + + The first collision appends ``(1)`` before the suffix, followed by ``(2)`` + and so on. Checking all related suffixes keeps an evaluation result JSON and + its artifacts directory on the same collision number. + """ + + if not suffixes: + raise ValueError("at least one output suffix is required") + number = 0 + while True: + candidate = base_name if number == 0 else f"{base_name}({number})" + if all( + not (directory / f"{candidate}{suffix}").exists() for suffix in suffixes + ): + return candidate + number += 1 diff --git a/tests/traces/test_trace_report.py b/tests/traces/test_trace_report.py index f313e70..19e7a4a 100644 --- a/tests/traces/test_trace_report.py +++ b/tests/traces/test_trace_report.py @@ -11,6 +11,8 @@ TRACE_SCHEMA_VERSION, TraceFormatError, TraceWriter, + build_trace_run, + read_located_trace, read_trace, reconstruct_model_request, render_trace_report, @@ -55,7 +57,9 @@ def test_trace_events_have_correlation_metadata_and_redaction(tmp_path: Path) -> assert "Run: run-test" in report assert "Trace level: summary" in report assert "Outcome: unfinished" in report - assert "step=1 assistant duration=7ms" in report + assert "Step 1/1 — fake 7ms 12 tokens [L2]" in report + assert "Model call [request missing → response L2]" in report + assert "Reasoning: 13 chars" in report def test_debug_trace_includes_reasoning_and_redacts_common_secrets( @@ -249,7 +253,8 @@ def test_report_marks_trace_without_run_end_as_interrupted(tmp_path: Path) -> No report = render_trace_report(path) assert "Outcome: interrupted (no run_end event)" in report - assert "model_error TimeoutError: timed out" in report + assert "Model call [request missing → error L2]" in report + assert "Error: TimeoutError: timed out" in report def test_report_rejects_malformed_jsonl(tmp_path: Path) -> None: @@ -270,3 +275,229 @@ def test_agent_clis_expose_trace_level() -> None: assert eval_args.trace_level == "debug" assert "--trace-reasoning" not in build_run_parser().format_help() assert "--trace-reasoning" not in build_eval_parser().format_help() + + +def test_grouped_report_preserves_lines_and_multi_tool_order(tmp_path: Path) -> None: + path = tmp_path / "multi-tool.jsonl" + records = [ + _record( + 1, + "run_start", + { + "model": "deepseek-v4-pro", + "task": "fix parser", + "max_steps": 30, + "trace_level": "summary", + }, + ), + _record(2, "model_request", {"step": 1, "request_id": "request-1"}), + _record( + 3, + "assistant", + { + "step": 1, + "request_id": "request-1", + "duration_ms": 1800, + "finish_reason": "tool_calls", + "usage": {"total_tokens": 1246}, + "message": { + "reasoning_content": {"redacted": True, "chars": 381}, + "tool_calls": [], + }, + }, + ), + _record(4, "plan_decision", {"step": 1, "action": "execute_tools"}), + _record( + 5, + "tool_call", + {"step": 1, "tool_call_id": "search", "tool": "search_code"}, + ), + _record( + 6, + "tool_call", + {"step": 1, "tool_call_id": "command", "tool": "run_command"}, + ), + _record( + 7, + "tool_result", + { + "step": 1, + "tool_call_id": "command", + "tool": "run_command", + "duration_ms": 37, + "result": {"ok": True, "exit_code": 1}, + }, + ), + _record( + 8, + "tool_result", + { + "step": 1, + "tool_call_id": "search", + "tool": "search_code", + "duration_ms": 42, + "result": {"ok": True}, + }, + ), + _record(9, "run_end", {"finished": True, "steps": 1}), + ] + path.write_text( + json.dumps(records[0]) + + "\n\n" + + "\n".join(json.dumps(record) for record in records[1:]) + + "\n", + encoding="utf-8", + ) + + located = read_located_trace(path) + run = build_trace_run(located) + report = render_trace_report(path) + + assert [event.line_number for event in located[:3]] == [1, 3, 4] + assert "line_number" not in read_trace(path)[1] + assert run.steps[0].first_line == 3 + assert run.steps[0].last_line == 9 + assert "Step 1/30 — deepseek-v4-pro 1.8s 1,246 tokens [L3–L9]" in report + assert "Model call [request L3 → response L4]" in report + assert "Finish reason: tool_calls" in report + assert "Reasoning: 381 chars" in report + assert "Plan: execute_tools [L5]" in report + search = "[ok] search_code 42ms [call L6 → result L9]" + command = "[ok] run_command 37ms exit=1 [call L7 → result L8]" + assert search in report + assert command in report + assert report.index(search) < report.index(command) + + +def test_report_marks_missing_model_response_and_tool_result(tmp_path: Path) -> None: + path = tmp_path / "interrupted.jsonl" + records = [ + _record(1, "run_start", {"model": "fake", "max_steps": 30}), + _record(2, "model_request", {"step": 7, "request_id": "request-7"}), + _record( + 3, + "tool_call", + {"step": 7, "tool_call_id": "orphan", "tool": "read_file"}, + ), + ] + path.write_text( + "\n".join(json.dumps(record) for record in records) + "\n", + encoding="utf-8", + ) + + report = render_trace_report(path) + + assert "Step 7/30 — interrupted [L2–L3]" in report + assert "Model call [request L2 → response missing]" in report + assert "[missing] read_file [call L3 → result missing]" in report + + +def test_protocol_violation_and_failed_tool_keep_line_references( + tmp_path: Path, +) -> None: + path = tmp_path / "violation.jsonl" + records = [ + _record(1, "model_request", {"step": 2, "request_id": "request-2"}), + _record( + 2, + "assistant", + { + "step": 2, + "request_id": "request-2", + "duration_ms": 5, + "finish_reason": "tool_calls", + "message": {"reasoning_content": "bad call"}, + }, + ), + _record( + 3, + "plan_decision", + { + "step": 2, + "action": "execute_tools", + "rejection_error": "duplicate finish calls", + }, + ), + _record( + 4, + "protocol_violation", + {"step": 2, "error": "duplicate finish calls"}, + ), + _record( + 5, + "tool_call", + {"step": 2, "tool_call_id": "bad", "tool": "finish"}, + ), + _record( + 6, + "tool_result", + { + "step": 2, + "tool_call_id": "bad", + "tool": "finish", + "duration_ms": 0, + "result": {"ok": False, "error": "duplicate finish calls"}, + }, + ), + _record( + 7, + "protocol_reminder", + {"step": 2, "text": "use the required tool protocol"}, + ), + ] + path.write_text( + "\n".join(json.dumps(record) for record in records) + "\n", + encoding="utf-8", + ) + + report = render_trace_report(path) + + assert "Plan: execute_tools [L3]" in report + assert "Protocol violation: duplicate finish calls [L4]" in report + assert "Protocol reminder: use the required tool protocol [L7]" in report + assert "[error] finish 0ms [call L5 → result L6]" in report + + +def test_step_verbose_events_and_flat_event_mode_use_physical_lines( + tmp_path: Path, capsys +) -> None: + path = tmp_path / "expanded.jsonl" + path.write_text( + json.dumps(_record(10, "model_request", {"step": 3, "request_id": "r"})) + + "\n\n" + + json.dumps( + _record( + 11, + "assistant", + { + "request_id": "r", + "finish_reason": "stop", + "message": {"content": "done"}, + }, + ) + ) + + "\n", + encoding="utf-8", + ) + + detail = render_trace_report(path, step=3) + flat = render_trace_report(path, events=True) + + assert "L1 model_request sequence=10" in detail + assert "L3 assistant sequence=11" in detail + assert "Model call [request L1 → response L3]" in detail + assert "L1 [ 10" in flat + assert "L3 [ 11" in flat + assert run_cli([str(path), "--events"]) == 0 + assert "L3 [ 11" in capsys.readouterr().out + + +def _record(sequence: int, event: str, data: dict) -> dict: + return { + "schema_version": TRACE_SCHEMA_VERSION, + "run_id": "test-run", + "sequence": sequence, + "elapsed_ms": sequence, + "event": event, + "data": data, + } diff --git a/tests/utils/test_naming.py b/tests/utils/test_naming.py index 175ceed..6630931 100644 --- a/tests/utils/test_naming.py +++ b/tests/utils/test_naming.py @@ -1,10 +1,13 @@ from __future__ import annotations from datetime import datetime, timedelta, timezone +from pathlib import Path import pytest -from yada.utils.naming import readable_run_name, task_slug +from yada.evals.cli import _default_output_path +from yada.run.cli import _default_trace_path +from yada.utils.naming import next_available_run_name, readable_run_name, task_slug def test_task_slug_keeps_meaningful_unicode_and_removes_unsafe_characters() -> None: @@ -23,7 +26,7 @@ def test_task_slug_is_bounded() -> None: task_slug("task", max_length=0) -def test_readable_run_name_uses_utc_and_microseconds() -> None: +def test_readable_run_name_uses_local_wall_time_without_seconds() -> None: china_time = datetime( 2026, 8, @@ -36,5 +39,52 @@ def test_readable_run_name_uses_utc_and_microseconds() -> None: ) assert readable_run_name("Pytest 10051", now=china_time) == ( - "pytest-10051__2026-08-02_12-26-26.123456Z" + "pytest-10051__2026-08-02_20-26" ) + + +def test_next_available_run_name_numbers_related_output_collisions( + tmp_path, +) -> None: + base_name = "pytest-dev__pytest-10051__2026-08-03_10-09" + (tmp_path / f"{base_name}.artifacts").mkdir() + (tmp_path / f"{base_name}(1).json").write_text("{}", encoding="utf-8") + + assert ( + next_available_run_name( + tmp_path, + base_name, + suffixes=(".json", ".artifacts"), + ) + == f"{base_name}(2)" + ) + + +def test_next_available_run_name_requires_an_output_suffix(tmp_path) -> None: + with pytest.raises(ValueError, match="at least one"): + next_available_run_name(tmp_path, "run", suffixes=()) + + +def test_default_eval_paths_number_an_existing_artifacts_directory( + tmp_path, monkeypatch +) -> None: + run_name = "pytest-dev__pytest-10051__2026-08-03_10-09" + results = tmp_path / "eval-results" + results.mkdir() + (results / f"{run_name}.artifacts").mkdir() + monkeypatch.chdir(tmp_path) + monkeypatch.setattr("yada.evals.cli.readable_run_name", lambda _: run_name) + + assert _default_output_path("case") == ( + Path("eval-results") / f"{run_name}(1).json" + ) + + +def test_default_trace_path_numbers_an_existing_trace(tmp_path, monkeypatch) -> None: + run_name = "fix-parser__2026-08-03_10-09" + directory = tmp_path / ".yada" / "runs" + directory.mkdir(parents=True) + (directory / f"{run_name}.jsonl").write_text("", encoding="utf-8") + monkeypatch.setattr("yada.run.cli.readable_run_name", lambda _: run_name) + + assert _default_trace_path(tmp_path, "task") == (directory / f"{run_name}(1).jsonl")