Skip to content

Commit ad3db3f

Browse files
lwgrayclaude
andauthored
fix(cost): close runs rows on completion (#537) (#538)
* fix(cost): close runs rows on completion (#537) What changed ------------ - ``CostStore.close_run`` stamps ``ended_at`` plus task/agent counters with a COALESCE-guarded UPDATE (live values win, NULL preserves existing). - ``CostStore.close_open_runs_for_project`` bulk-closes every open run for a project; called from ``end_experiment`` after ``monitor.stop()``. - ``CostAggregator.run_audit`` reports ``run_open``; ``project_audit`` reports ``runs_total`` and ``runs_open`` so the audit can detect the "every run open since insertion" failure mode. - ``scripts/backfill_run_close_state.py`` walks every NULL row and derives ``ended_at`` from ``MAX(token_events.timestamp) WHERE run_id = ?`` — best on-disk approximation for unattended close. Why --- The ``runs`` table has lifecycle columns the schema anticipates, but nothing in the Python code ever wrote them after #522. Every row has been "open" since insertion, blocking dashboard queries on ``ended_at IS NOT NULL`` and any wall-clock-time analysis (run duration, cost-per-minute, coordination-tax rate). The token-audit work in #528 confirmed token attribution but never asserted lifecycle closure — so the gap stayed silent. Real-data validation -------------------- Ran backfill on ``~/.marcus/costs.db``: $ python scripts/backfill_run_close_state.py Closed 1 runs. $ sqlite3 ~/.marcus/costs.db \ "SELECT COUNT(*), SUM(ended_at IS NULL) FROM runs;" 1|0 Test plan --------- - [x] ``pytest tests/unit/cost_tracking/`` — 95 passed (11 new) - [x] ``mypy src/cost_tracking/cost_store.py src/cost_tracking/cost_aggregator.py`` clean - [x] Backfill script ran end-to-end against real costs.db Related ------- - Closes #537 - Follows #522 (which added ``record_run`` without a close path) and #528 (which audited tokens but not lifecycle) Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> * fix(cost): canonicalize project_id in close_open_runs_for_project (#537) ``record_run`` stored the dashless UUID form via ``canonical_project_id``, but ``end_experiment`` passed ``monitor.project_id`` straight through. When the monitor was handed the dashed UUID form (ProjectRegistry path), the live close lookup matched zero rows and silently closed nothing — leaving the backfill script as the only safety net. Normalize at the close-helper entry: ``canonical_project_id(...)`` or fall back to the original string for non-UUID inputs (matches the rest of the cost layer, which normalizes on the way in). Regression test asserts a dashed input still closes the dashless row in ``runs``. Caught by Kaia on PR #538 review. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> * comment to not fix code * fix(cost): close only latest open run per project on end_experiment (#537) The cost schema allows multiple ``runs`` rows per ``project_id`` (retries, repeated traversals — ``run_id`` is the PK, project views group/list runs). The bulk close in ``close_open_runs_for_project`` stamped every historical open row for the project with the just-finished experiment's ``ended_at`` and final counters, corrupting older runs. Replace with ``close_latest_open_run_for_project``: scope to the ``MAX(started_at)`` open run only. Older open rows are left to the periodic ``backfill_run_close_state.py`` script, which derives ``ended_at`` from each row's own ``MAX(token_events.timestamp)`` — the on-disk approximation that's correct per-run rather than a batch-overwrite from the live hook. Return type tightened from ``int`` (count) to ``Optional[str]`` (the closed run_id) so callers can log which row was touched. Caught by Codex P2 on PR #538. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
1 parent 24188c4 commit ad3db3f

7 files changed

Lines changed: 645 additions & 5 deletions

File tree

Lines changed: 103 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,103 @@
1+
#!/usr/bin/env python3
2+
"""
3+
One-shot backfill of ``runs.ended_at`` from ``token_events.timestamp``.
4+
5+
The ``runs`` table has lifecycle columns (``ended_at``, ``total_tasks``,
6+
``completed_tasks``, etc.) that the schema clearly anticipates, but
7+
until Marcus #537 no Python code ever wrote them. Every row in ``runs``
8+
has been "open" since insertion. This blocks any dashboard query
9+
filtering on ``ended_at IS NOT NULL`` and prevents wall-clock-time
10+
analysis (cost-per-minute, coordination tax rate, run duration).
11+
12+
Going forward, ``end_experiment`` closes runs live for the
13+
``path=marcus`` and ``path=posidonius`` flows. This backfill closes
14+
the rest: historical runs that pre-date the fix, and runs from
15+
``path=direct`` usage where the user never invokes ``end_experiment``.
16+
17+
Heuristic
18+
---------
19+
For each ``runs`` row where ``ended_at IS NULL``, set ``ended_at`` to
20+
``MAX(timestamp) FROM token_events WHERE run_id = ?`` — the timestamp
21+
of the last LLM call attributed to that run. That's the best on-disk
22+
approximation we have for unattended close. Runs with zero token
23+
events are left open (genuinely empty runs are ambiguous and likely
24+
indicate the run died before any LLM call).
25+
26+
Idempotent: re-runnable. Rows with ``ended_at`` already set are
27+
skipped (the CostStore's UPDATE only fills NULL fields).
28+
29+
Usage
30+
-----
31+
.. code-block:: console
32+
33+
$ python scripts/backfill_run_close_state.py
34+
Closed 23 runs (10 had zero events and were skipped).
35+
36+
Pass ``--costs-db PATH`` to override the cost-store path (defaults
37+
to ``~/.marcus/costs.db``).
38+
"""
39+
40+
from __future__ import annotations
41+
42+
import argparse
43+
import sys
44+
from pathlib import Path
45+
from typing import Tuple
46+
47+
_REPO_ROOT = Path(__file__).resolve().parent.parent
48+
sys.path.insert(0, str(_REPO_ROOT))
49+
50+
from src.cost_tracking.cost_store import CostStore # noqa: E402
51+
52+
53+
def _parse_args() -> argparse.Namespace:
54+
parser = argparse.ArgumentParser(description=__doc__.split("\n\n")[0])
55+
parser.add_argument(
56+
"--costs-db",
57+
type=Path,
58+
default=Path.home() / ".marcus" / "costs.db",
59+
help="Path to costs.db (default: ~/.marcus/costs.db).",
60+
)
61+
return parser.parse_args()
62+
63+
64+
def backfill(costs_db: Path) -> Tuple[int, int]:
65+
"""Close every open run whose token_events have a max timestamp.
66+
67+
Returns
68+
-------
69+
(closed, skipped) : tuple of int
70+
Counts for runs successfully closed and runs left open
71+
because they had zero token_events.
72+
"""
73+
store = CostStore(db_path=costs_db)
74+
75+
open_rows = store.conn.execute(
76+
"SELECT run_id FROM runs WHERE ended_at IS NULL"
77+
).fetchall()
78+
79+
closed = 0
80+
skipped = 0
81+
for (run_id,) in open_rows:
82+
# ``close_run`` returns False when there are no events to
83+
# derive ended_at from — those runs stay open.
84+
if store.close_run(run_id):
85+
closed += 1
86+
else:
87+
skipped += 1
88+
return closed, skipped
89+
90+
91+
def main() -> int:
92+
"""Parse CLI args, run the backfill, and print a summary."""
93+
args = _parse_args()
94+
closed, skipped = backfill(args.costs_db)
95+
print(
96+
f"Closed {closed} runs"
97+
+ (f" ({skipped} had zero events and were skipped)." if skipped > 0 else ".")
98+
)
99+
return 0
100+
101+
102+
if __name__ == "__main__":
103+
raise SystemExit(main())

src/cost_tracking/cost_aggregator.py

Lines changed: 39 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -361,24 +361,59 @@ def run_audit(self, run_id: str) -> Dict[str, Any]:
361361
or ``agent_id``. A healthy audit shows ``reconciles=True`` and
362362
zero ``worker_events_without_task_id``.
363363
364+
Also reports run-lifecycle status (Marcus #537): ``run_open``
365+
is True when the run's ``ended_at`` is NULL — i.e. the row
366+
was written at create_project time but never closed. A
367+
complete audit cares about both token reconciliation AND
368+
lifecycle closure.
369+
364370
Returns
365371
-------
366372
dict
367373
``total_events``, ``total_tokens``, ``by_role_total_tokens``,
368374
``reconciles`` (bool), ``tokens_outside_known_roles``,
369375
``planner_events``, ``worker_events``,
370376
``worker_events_without_task_id``,
371-
``worker_events_without_agent_id``.
377+
``worker_events_without_agent_id``, ``run_open`` (bool).
372378
"""
373-
return self._audit_query("run_id = ?", (run_id,))
379+
audit = self._audit_query("run_id = ?", (run_id,))
380+
row = self._row("SELECT ended_at FROM runs WHERE run_id = ?", (run_id,))
381+
# ``run_open`` is True only when a run exists and has no
382+
# ended_at. An unknown run_id yields False to avoid noise.
383+
audit["run_open"] = row is not None and row.get("ended_at") is None
384+
return audit
374385

375386
def project_audit(self, project_id: str) -> Dict[str, Any]:
376387
"""Token-attribution audit for one project (Marcus #527).
377388
378389
Like :meth:`run_audit` but scoped to all runs for one
379-
``project_id``. Same return shape — see that docstring.
390+
``project_id``. Reports the same token-attribution fields plus
391+
project-level lifecycle counts (Marcus #537): ``runs_total``
392+
and ``runs_open`` for the runs attributed to this project.
393+
394+
Returns
395+
-------
396+
dict
397+
All fields from :meth:`run_audit` minus ``run_open``, plus
398+
``runs_total`` and ``runs_open``.
380399
"""
381-
return self._audit_query("project_id = ?", (project_id,))
400+
audit = self._audit_query("project_id = ?", (project_id,))
401+
row = (
402+
self._row(
403+
"""
404+
SELECT COUNT(*) AS total,
405+
COALESCE(SUM(CASE WHEN ended_at IS NULL THEN 1 ELSE 0 END), 0)
406+
AS open_count
407+
FROM runs
408+
WHERE project_id = ?
409+
""",
410+
(project_id,),
411+
)
412+
or {"total": 0, "open_count": 0}
413+
)
414+
audit["runs_total"] = int(row.get("total", 0) or 0)
415+
audit["runs_open"] = int(row.get("open_count", 0) or 0)
416+
return audit
382417

383418
def cache_hit_rate_by_agent(self, run_id: str) -> List[Dict[str, Any]]:
384419
"""Per-agent cache hit rate within one experiment.

src/cost_tracking/cost_store.py

Lines changed: 150 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -905,6 +905,156 @@ def record_run(self, run: Run) -> None:
905905
)
906906
self.conn.commit()
907907

908+
def close_run(
909+
self,
910+
run_id: str,
911+
*,
912+
ended_at: Optional[datetime] = None,
913+
total_tasks: Optional[int] = None,
914+
completed_tasks: Optional[int] = None,
915+
blocked_tasks: Optional[int] = None,
916+
num_agents: Optional[int] = None,
917+
) -> bool:
918+
"""Stamp final-state lifecycle fields on a run (Marcus #537).
919+
920+
Closes the data-quality gap where every ``runs`` row stayed
921+
open forever because the only writer
922+
(``create_project`` → ``record_run``) only wrote the open
923+
state. The dataclass and UPSERT have always supported the
924+
close fields; this method is the missing caller.
925+
926+
When ``ended_at`` is ``None``, falls back to the timestamp of
927+
the most recent ``token_events`` row attributed to this run —
928+
the best on-disk approximation for unattended close
929+
(``path=direct`` usage where the user never calls
930+
``end_experiment``). When no events exist for the run, the
931+
method returns False without updating, since "closed with no
932+
activity" is ambiguous and likely indicates the run died
933+
before any LLM call.
934+
935+
Uses a targeted UPDATE rather than the upsert path so passing
936+
``None`` for a field leaves the existing column value
937+
untouched (COALESCE-guarded). Safe to re-run; idempotent on
938+
already-closed rows.
939+
940+
Parameters
941+
----------
942+
run_id : str
943+
The run to close.
944+
ended_at : datetime, optional
945+
Wall-clock end time. When None, derives from the run's
946+
last event timestamp.
947+
total_tasks, completed_tasks, blocked_tasks, num_agents : int, optional
948+
Final lifecycle counts. None leaves the existing value.
949+
950+
Returns
951+
-------
952+
bool
953+
True if a row was updated, False if the run_id was
954+
unknown or had no events to back into ``ended_at``.
955+
"""
956+
# Resolve ended_at via the last event timestamp when the
957+
# caller didn't supply one. This is the unattended-close path
958+
# — backfill scripts and direct-MCP runs land here.
959+
resolved_ended_at_iso: Optional[str]
960+
if ended_at is not None:
961+
resolved_ended_at_iso = ended_at.isoformat()
962+
else:
963+
row = self.conn.execute(
964+
"SELECT MAX(timestamp) FROM token_events WHERE run_id = ?",
965+
(run_id,),
966+
).fetchone()
967+
if row is None or row[0] is None:
968+
# No events for this run — can't infer ended_at.
969+
# Caller should pass an explicit value or skip.
970+
return False
971+
resolved_ended_at_iso = str(row[0])
972+
973+
cur = self.conn.execute(
974+
"""
975+
UPDATE runs
976+
SET ended_at = COALESCE(?, ended_at),
977+
total_tasks = COALESCE(?, total_tasks),
978+
completed_tasks = COALESCE(?, completed_tasks),
979+
blocked_tasks = COALESCE(?, blocked_tasks),
980+
num_agents = COALESCE(?, num_agents)
981+
WHERE run_id = ?
982+
""",
983+
(
984+
resolved_ended_at_iso,
985+
total_tasks,
986+
completed_tasks,
987+
blocked_tasks,
988+
num_agents,
989+
run_id,
990+
),
991+
)
992+
self.conn.commit()
993+
return cur.rowcount > 0
994+
995+
def close_latest_open_run_for_project(
996+
self,
997+
project_id: str,
998+
*,
999+
ended_at: Optional[datetime] = None,
1000+
total_tasks: Optional[int] = None,
1001+
completed_tasks: Optional[int] = None,
1002+
blocked_tasks: Optional[int] = None,
1003+
num_agents: Optional[int] = None,
1004+
) -> Optional[str]:
1005+
"""Close the most recently started open run for a project (#537).
1006+
1007+
Live-close hook for ``end_experiment``. The schema allows
1008+
multiple ``runs`` rows per ``project_id`` (retries, repeated
1009+
traversals), so a bulk close would stamp every historical
1010+
open row with the just-finished experiment's
1011+
``ended_at`` / counters — corrupting older runs.
1012+
1013+
Scope the close to the latest open run, identified by
1014+
``MAX(started_at)``. Older open rows for the same project are
1015+
left to the periodic ``backfill_run_close_state.py``, which
1016+
derives ``ended_at`` from each row's own
1017+
``MAX(token_events.timestamp)``.
1018+
1019+
The incoming ``project_id`` is normalized via
1020+
:func:`src.cost_tracking.cost_recorder.canonical_project_id`
1021+
so callers can pass either dashed UUID form (ProjectRegistry)
1022+
or dashless hex form (SQLiteKanban auto-discovery) — both
1023+
resolve to the dashless form actually stored in ``runs``.
1024+
Without this, the live close silently no-ops whenever the
1025+
monitor was handed a dashed project_id.
1026+
1027+
Returns
1028+
-------
1029+
Optional[str]
1030+
The closed ``run_id``, or ``None`` if the project had no
1031+
open runs.
1032+
"""
1033+
from src.cost_tracking.cost_recorder import canonical_project_id
1034+
1035+
normalized = canonical_project_id(project_id) or project_id
1036+
row = self.conn.execute(
1037+
"""
1038+
SELECT run_id FROM runs
1039+
WHERE project_id = ? AND ended_at IS NULL
1040+
ORDER BY started_at DESC
1041+
LIMIT 1
1042+
""",
1043+
(normalized,),
1044+
).fetchone()
1045+
if row is None:
1046+
return None
1047+
(run_id,) = row
1048+
closed = self.close_run(
1049+
run_id,
1050+
ended_at=ended_at,
1051+
total_tasks=total_tasks,
1052+
completed_tasks=completed_tasks,
1053+
blocked_tasks=blocked_tasks,
1054+
num_agents=num_agents,
1055+
)
1056+
return run_id if closed else None
1057+
9081058
def record_price(self, price: ModelPrice) -> None:
9091059
"""Insert one ``model_prices`` row.
9101060

src/marcus_mcp/coordinator/subtask_assignment.py

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -328,6 +328,39 @@ async def check_and_complete_parent_task(
328328
# task to the agent that drove it to completion (Bug 3 fix).
329329
# Without this, the parent appears as a ghost completion with no
330330
# agent record — invisible in experiment analytics.
331+
#
332+
# DELIBERATELY NOT WRITING task_outcomes HERE — see contract below.
333+
#
334+
# Auto-completion contract (do not change without an ADR):
335+
#
336+
# Parents-with-subtasks are coordination containers. The work data
337+
# (started_at, completed_at, actual_hours, agent_id) lives on the
338+
# subtask outcomes — which are real per-agent records written via
339+
# Memory.record_task_completion when each subtask finishes.
340+
#
341+
# Writing a synthetic parent outcome here would corrupt agent
342+
# learning:
343+
# * Memory._update_agent_profile (memory.py) ticks
344+
# total_tasks + skill_success_rates EMA per outcome row;
345+
# a parent row attributed to completing_agent_id would
346+
# double-count their work.
347+
# * analysis.aggregator._build_agent_histories sums
348+
# outcome.actual_hours into total_hours, also double-counting.
349+
# * Scheduler tests (test_scheduler_prototype_mode.py) already
350+
# assert "parent with subtasks is a container — should be
351+
# excluded" from CPM. Outcome accounting must match that.
352+
#
353+
# Contrast with About/design auto-completion in nlp_tools.py:
354+
# those write task_outcomes with agent_id="system" or "Marcus",
355+
# synthetic IDs that don't correspond to a real worker and so
356+
# don't pollute learning. Those tasks are LEAVES with no
357+
# subtasks — the outcome write is the only place their data
358+
# lives. Subtask-driven parents are DERIVATIVE — the data
359+
# already lives on the subtasks.
360+
#
361+
# Downstream observers (Cato) aggregate subtask data for parent
362+
# display rather than relying on a parent outcome row. See
363+
# cato_src/core/aggregator._apply_subtask_rollup.
331364
if completing_agent_id and state and hasattr(state, "log_event"):
332365
state.log_event(
333366
"task_assignment",

0 commit comments

Comments
 (0)