From 15e43fc44f87d238e25bb83270b921b82a4380cb Mon Sep 17 00:00:00 2001 From: SpiliosDmk Date: Thu, 23 Jul 2026 14:20:07 +0300 Subject: [PATCH] feat: surface per-stage duration in report (closes #200) --- docs/usage.md | 4 + src/readme2demo/cli.py | 6 +- src/readme2demo/manifest.py | 25 ++++++ src/readme2demo/orchestrator.py | 23 +++++- tests/test_cli.py | 42 +++++++++- tests/test_orchestrator.py | 132 +++++++++++++++++++++++++++++--- 6 files changed, 214 insertions(+), 18 deletions(-) diff --git a/docs/usage.md b/docs/usage.md index 7a6c956..a11c2f1 100644 --- a/docs/usage.md +++ b/docs/usage.md @@ -57,6 +57,10 @@ directly instead of parsing output: | `1` | Completed but **UNVERIFIED** — no stage failed, but the replay did not pass. | | `2` | A stage failed. | +`report` also shows how long each stage took (from the timestamps already in +`manifest.json`): a duration column in the human and `--markdown` tables, and +a numeric `duration_seconds` per stage in `--json` (`null` when unknown). + ```bash readme2demo report runs/tool-20260702-... --json && echo "verified" || echo "gate failed" ``` diff --git a/src/readme2demo/cli.py b/src/readme2demo/cli.py index 4800c46..ad259b9 100644 --- a/src/readme2demo/cli.py +++ b/src/readme2demo/cli.py @@ -537,7 +537,11 @@ def report( if json_output: output_data = { "stages": [ - {"name": name, "status": rec.status} + { + "name": name, + "status": rec.status, + "duration_seconds": rec.duration_seconds, + } for name, rec in manifest.stages.items() ], "verified": manifest.verified, diff --git a/src/readme2demo/manifest.py b/src/readme2demo/manifest.py index bf792e1..4b45294 100644 --- a/src/readme2demo/manifest.py +++ b/src/readme2demo/manifest.py @@ -37,6 +37,31 @@ class StageRecord(BaseModel): cost_usd: float = 0.0 meta: dict = Field(default_factory=dict) + @property + def duration_seconds(self) -> Optional[float]: + """Elapsed wall-clock time for this stage's last attempt, in seconds. + + Returns ``None`` (not ``0``) whenever the duration isn't knowable: + missing ``started_at``/``finished_at``, unparseable timestamps, or a + negative span (clock skew / a hand-edited manifest). A plain + ``@property`` on purpose -- pydantic only serializes ``@computed_field``s, + so this never changes the on-disk shape of ``manifest.json``. + """ + if self.started_at is None or self.finished_at is None: + return None + + try: + started = datetime.fromisoformat(self.started_at) + finished = datetime.fromisoformat(self.finished_at) + except ValueError: + return None + + elapsed = (finished - started).total_seconds() + if elapsed < 0: + return None + + return elapsed + class Manifest(BaseModel): run_id: str diff --git a/src/readme2demo/orchestrator.py b/src/readme2demo/orchestrator.py index 10068e5..ffab2c5 100644 --- a/src/readme2demo/orchestrator.py +++ b/src/readme2demo/orchestrator.py @@ -360,6 +360,19 @@ def run(self) -> Manifest: return self.manifest +def _format_duration(seconds: Optional[float]) -> str: + """Render a stage duration for human/markdown output. + + ``None`` (unknown duration) renders as a visible placeholder, never a + blank or ``0.0s`` -- those would look like data instead of "we don't + know". A genuinely sub-second stage still shows a real number (``0.0s``), + so it isn't mistaken for "unknown" either. + """ + if seconds is None: + return "—" + return f"{seconds:.1f}s" + + def summarize(manifest: Manifest) -> str: """Human-readable run report for ``readme2demo report``.""" repo_line = ( @@ -380,7 +393,8 @@ def summarize(manifest: Manifest) -> str: meta = "" if rec.meta: meta = " " + json.dumps(rec.meta, default=str) - lines.append(f" {name:<10} {rec.status:<10}{meta}{extra}") + duration = _format_duration(rec.duration_seconds) + lines.append(f" {name:<10} {rec.status:<10} {duration:<8}{meta}{extra}") return "\n".join(lines) @@ -417,14 +431,15 @@ def summarize_markdown(manifest: Manifest, artifacts: list[str]) -> str: f"{badge} — {repo_part} — engine `{manifest.engine}` — " f"total cost ${manifest.total_cost_usd:.4f}", "", - "| Stage | Status | Cost (USD) | Notes |", - "|---|---|---|---|", + "| Stage | Status | Cost (USD) | Duration | Notes |", + "|---|---|---|---|---|", ] for name, rec in manifest.stages.items(): # Failed stages carry `error`; skipped stages carry meta["reason"]. note = rec.error or rec.meta.get("reason", "") + duration = _format_duration(rec.duration_seconds) lines.append( - f"| {name} | {rec.status} | {rec.cost_usd:.4f} | {_md_cell(note)} |" + f"| {name} | {rec.status} | {rec.cost_usd:.4f} | {duration} | {_md_cell(note)} |" ) if artifacts: lines += ["", "**Artifacts**", ""] diff --git a/tests/test_cli.py b/tests/test_cli.py index 27e7a62..0d48bce 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -470,8 +470,42 @@ def test_regression_report_json_with_recorded_stages(tmp_path): assert parsed["verified"] is True assert parsed["cost"] == 1.5 assert parsed["commit"] == "abcdef123456" - assert {"name": "ingest", "status": "completed"} in parsed["stages"] - assert {"name": "agent", "status": "failed"} in parsed["stages"] + assert { + "name": "ingest", + "status": "completed", + "duration_seconds": None, + } in parsed["stages"] + assert { + "name": "agent", + "status": "failed", + "duration_seconds": None, + } in parsed["stages"] + + +def test_report_json_includes_known_duration(tmp_path): + """Regression (#200): a stage with real timestamps reports a numeric + duration_seconds; consumers must not have to parse a string like + "1m 25s" out of it.""" + import json + + manifest_data = { + "run_id": "duration-test-run", + "verified": True, + "stages": { + "ingest": { + "status": "completed", + "started_at": "2026-07-10T16:20:12+00:00", + "finished_at": "2026-07-10T16:20:22.5+00:00", + }, + }, + } + (tmp_path / "manifest.json").write_text(json.dumps(manifest_data)) + + result = runner.invoke(app, ["report", str(tmp_path), "--json"]) + + parsed = json.loads(result.output) + stage = next(s for s in parsed["stages"] if s["name"] == "ingest") + assert stage["duration_seconds"] == pytest.approx(10.5) # -- report exit codes (#85) -------------------------------------------------- @@ -594,8 +628,8 @@ def test_report_markdown_emits_gfm_summary_with_present_artifacts(tmp_path): out = result.output assert "## readme2demo — glow-20260710-162012-33fc72" in out assert "**Verified: yes**" in out - assert "| Stage | Status | Cost (USD) | Notes |" in out - assert "| ingest | completed | 0.0021 | |" in out + assert "| Stage | Status | Cost (USD) | Duration | Notes |" in out + assert "| ingest | completed | 0.0021 | — | |" in out assert "- tutorial.md" in out assert "- demo.mp4" in out assert "- demo.gif" not in out # not on disk → not claimed diff --git a/tests/test_orchestrator.py b/tests/test_orchestrator.py index 72ba618..8fae8f0 100644 --- a/tests/test_orchestrator.py +++ b/tests/test_orchestrator.py @@ -4,13 +4,14 @@ """ from pathlib import Path +import json import pytest from readme2demo import ingest as ingest_mod from readme2demo.config import Config -from readme2demo.manifest import STAGES, Manifest -from readme2demo.orchestrator import Orchestrator, PipelineError, summarize_markdown +from readme2demo.manifest import STAGES, Manifest, StageRecord +from readme2demo.orchestrator import Orchestrator, PipelineError, summarize, summarize_markdown from readme2demo.types import Plan, SuccessCriteria @@ -100,6 +101,82 @@ def test_manifest_skip_counts_as_done(tmp_path: Path): assert m.next_stage() == "tutorial" +# -- StageRecord.duration_seconds (#200) ---------------------------------------- +# A plain @property (not @computed_field) on purpose: pydantic only serializes +# computed fields, so this must never change manifest.json's on-disk shape. + + +def test_duration_seconds_completed_stage(): + """Regression: a completed stage reports elapsed wall-clock seconds.""" + rec = StageRecord( + status="completed", + started_at="2026-07-01T10:00:00+00:00", + finished_at="2026-07-01T10:00:12.500000+00:00", + ) + assert rec.duration_seconds == pytest.approx(12.5) + + +def test_duration_seconds_still_running_is_none(): + """Regression: a stage with started_at but no finished_at (still running, + or the process died mid-stage) is an unknown duration, not zero.""" + rec = StageRecord(status="running", started_at="2026-07-01T10:00:00+00:00") + assert rec.duration_seconds is None + + +def test_duration_seconds_skipped_without_start_is_none(): + """Regression: stage_skip sets finished_at without started_at when a stage + (e.g. via --skip-video) never actually started. Duration is unknown, not + a negative or zero number.""" + rec = StageRecord(status="skipped", finished_at="2026-07-01T10:00:00+00:00") + assert rec.duration_seconds is None + + +def test_duration_seconds_pending_stage_is_none(): + rec = StageRecord() + assert rec.duration_seconds is None + + +def test_duration_seconds_unparseable_timestamp_is_none(): + """Regression: a hand-edited or corrupt manifest shouldn't raise — an + unparseable timestamp is an unknown duration.""" + rec = StageRecord(status="completed", started_at="not-a-date", finished_at="also-not-a-date") + assert rec.duration_seconds is None + + +def test_duration_seconds_negative_span_is_none(): + """Regression: clock skew or a hand-edited manifest where finished_at + precedes started_at must not report a negative duration.""" + rec = StageRecord( + status="completed", + started_at="2026-07-01T10:00:10+00:00", + finished_at="2026-07-01T10:00:00+00:00", + ) + assert rec.duration_seconds is None + + +def test_duration_seconds_zero_length_stage_is_not_none(): + """A genuinely sub-second stage (e.g. `normalize`) is real elapsed time, + not "unknown" — must not be conflated with the None cases above.""" + rec = StageRecord( + status="completed", + started_at="2026-07-01T10:00:00+00:00", + finished_at="2026-07-01T10:00:00+00:00", + ) + assert rec.duration_seconds == 0.0 + + +def test_duration_seconds_not_serialized_to_manifest_json(tmp_path: Path): + """Regression: exposing duration via @computed_field would serialize it + into every manifest.json write, changing the on-disk schema of a + crash-safe state file for a cosmetic report feature. Must stay a plain + property.""" + m = Manifest.create(tmp_path / "r5", "https://github.com/x/y", "claude-code", "img") + m.stage_start("ingest") + m.stage_complete("ingest") + raw = json.loads((tmp_path / "r5" / "manifest.json").read_text()) + assert "duration_seconds" not in raw["stages"]["ingest"] + + # -- orchestrator control flow --------------------------------------------------- @@ -324,10 +401,10 @@ def test_summarize_markdown_verified_run_full_shape(): assert "engine `claude-code`" in badge assert "total cost $0.1234" in badge # Stages table: header + one row per recorded stage, with per-stage cost. - assert "| Stage | Status | Cost (USD) | Notes |" in lines - assert "| ingest | completed | 0.0021 | |" in lines - assert "| agent | completed | 0.0980 | |" in lines - assert "| verify | completed | 0.0000 | |" in lines + assert "| Stage | Status | Cost (USD) | Duration | Notes |" in lines + assert "| ingest | completed | 0.0021 | — | |" in lines + assert "| agent | completed | 0.0980 | — | |" in lines + assert "| verify | completed | 0.0000 | — | |" in lines # Artifact list renders exactly what the caller passed. assert "**Artifacts**" in lines assert "- tutorial.md" in lines @@ -355,7 +432,7 @@ def test_summarize_markdown_failed_stage_error_in_notes(): stages={"agent": {"status": "failed", "error": "exit 127: no engine"}}, ) md = summarize_markdown(m, []) - assert "| agent | failed | 0.0000 | exit 127: no engine |" in md.splitlines() + assert "| agent | failed | 0.0000 | — | exit 127: no engine |" in md.splitlines() def test_summarize_markdown_skip_reason_in_notes(): @@ -363,7 +440,7 @@ def test_summarize_markdown_skip_reason_in_notes(): stages={"render": {"status": "skipped", "meta": {"reason": "dry-run stop"}}}, ) md = summarize_markdown(m, []) - assert "| render | skipped | 0.0000 | dry-run stop |" in md.splitlines() + assert "| render | skipped | 0.0000 | — | dry-run stop |" in md.splitlines() def test_summarize_markdown_escapes_table_breaking_error_text(): @@ -384,9 +461,46 @@ def test_summarize_markdown_escapes_table_breaking_error_text(): assert len(rows) == 1 # newlines collapsed — still one table row assert "\\|" in rows[0] # pipe escaped, cell not split assert "[openai]" in rows[0] # brackets survive verbatim - assert rows[0].count(" | ") == 3 # exactly 4 cells + assert rows[0].count(" | ") == 4 # exactly 5 cells def test_summarize_markdown_no_artifacts_omits_section(): md = summarize_markdown(make_report_manifest(verified=False, stages={}), []) assert "**Artifacts**" not in md + + +def test_summarize_markdown_known_duration_rendered(): + """Regression: a stage with real timestamps shows a real Duration cell, + not the "—" unknown placeholder.""" + m = make_report_manifest( + stages={ + "ingest": { + "status": "completed", + "cost_usd": 0.0021, + "started_at": "2026-07-10T16:20:12+00:00", + "finished_at": "2026-07-10T16:20:23.700000+00:00", + }, + }, + ) + md = summarize_markdown(m, []) + assert "| ingest | completed | 0.0021 | 11.7s | |" in md.splitlines() + + +def test_summarize_human_report_shows_duration_column(): + m = make_report_manifest( + stages={ + "ingest": { + "status": "completed", + "started_at": "2026-07-10T16:20:12+00:00", + "finished_at": "2026-07-10T16:20:24+00:00", + }, + "agent": {"status": "pending"}, + }, + ) + text = summarize(m) + lines = text.splitlines() + ingest_line = next(ln for ln in lines if ln.strip().startswith("ingest")) + agent_line = next(ln for ln in lines if ln.strip().startswith("agent")) + assert "12.0s" in ingest_line + # A pending stage (no timestamps at all) is unknown, shown as "—". + assert "—" in agent_line