feat: Log loop claim decisions: which candidate was picked and why others were skipped (#124) (#127)

Author: mabry1985

loop.py

@@ -848,7 +848,16 @@ def _spawn_ready(self) -> bool:
         (``max_pending_reviews``), and skip a candidate whose ``files_to_modify``
         overlap an in-flight build (the hot-file guard — two parallel coders editing
         the same file are a guaranteed merge conflict). Returns True if it started at
-        least one drive (so the runner stays hot)."""
+        least one drive (so the runner stays hot).
+
+        Every tick that reaches the claim scan emits ONE parseable ``claim_decision``
+        ``log.info`` (#124): the fid(s) selected this tick and, for each higher-priority
+        ``ready_queue`` candidate passed over, the structured reason it was skipped
+        (hot-file overlap with which in-flight fid, ``claim()`` returned None, not
+        ready/blocked). That is the evidence to tell a lost claim race from the hot-file
+        guard from a ``ready_queue`` mis-ordering when a lower-priority card claims ahead
+        of a higher one — the payload is JSON, so a future observer parses it without
+        grepping log levels."""
         if len(self._drives) >= self.max_concurrent:
             return False
         # Fail-closed gate preflight: if the gate can't run on clean base, HOLD all work
@@ -861,24 +870,49 @@ def _spawn_ready(self) -> bool:
         if self.max_pending_reviews and len(store.list_features(state="in_review")) >= self.max_pending_reviews:
             return False
         spawned = False
-        busy = set().union(*self._inflight_files.values()) if self._inflight_files else set()
+        # file → the in-flight (or claimed-this-tick) fid that owns it, so a hot-file
+        # skip can NAME the build it collides with, not just report "some overlap".
+        file_owner: dict[str, str] = {}
+        for owner_fid, owner_files in self._inflight_files.items():
+            for path in owner_files:
+                file_owner.setdefault(path, owner_fid)
+        busy = set(file_owner)
+        selected: list[str] = []
+        skipped: list[dict] = []  # {fid, reason, …} per passed-over candidate, priority order
         for candidate in store.ready_queue(relaxed=self.relaxed_gate):  # priority order, dep-unblocked
             if len(self._drives) >= self.max_concurrent:
-                break
+                break  # remaining candidates are lower priority than what we already selected
+            cid = candidate["id"]
             if candidate.get("board_state") != "ready" or candidate.get("blocked"):
-                continue  # a blocked-flagged feature can carry the `ready` label too
+                # a blocked-flagged feature can carry the `ready` label too
+                reason = "blocked" if candidate.get("blocked") else f"state={candidate.get('board_state')}"
+                skipped.append({"fid": cid, "reason": reason})
+                continue
             files = set(candidate.get("files_to_modify") or [])
-            if files & busy:
-                continue  # would edit a file an in-flight build owns → defer a tick
-            claimed = store.claim(candidate["id"], assignee=self.coder_name)
+            overlap = files & busy
+            if overlap:
+                # would edit a file an in-flight build owns → defer a tick
+                owners = sorted({file_owner[p] for p in overlap})
+                skipped.append({"fid": cid, "reason": "hot-file", "overlaps": owners, "files": sorted(overlap)})
+                continue
+            claimed = store.claim(cid, assignee=self.coder_name)
             if claimed is None:
-                continue  # raced / no longer ready
+                skipped.append({"fid": cid, "reason": "claim-race"})  # raced / no longer ready
+                continue
             self._inflight_files[claimed["id"]] = files
+            for path in files:
+                file_owner.setdefault(path, claimed["id"])
             task = asyncio.create_task(self._drive(claimed), name=f"pb-drive-{claimed['id']}")
             self._drives.add(task)
             task.add_done_callback(self._make_drive_done_cb(claimed["id"]))
             busy |= files
+            selected.append(claimed["id"])
             spawned = True
+        if selected or skipped:
+            log.info(
+                "[project_board] claim_decision %s",
+                json.dumps({"selected": selected, "skipped": skipped}, separators=(",", ":"), sort_keys=True),
+            )
         return spawned
 
     def _make_drive_done_cb(self, fid: str):

tests/test_loop.py

@@ -11,6 +11,7 @@
 from __future__ import annotations
 
 import asyncio
+import json
 
 from project_board import worktree
 from project_board.loop import (
@@ -1098,6 +1099,61 @@ async def _quick(feature):
     assert loop._drives == set()
 
 
+async def test_spawn_ready_logs_the_claim_decision_with_skip_reason(monkeypatch, caplog):
+    """#124: when a lower-priority card claims ahead of a higher one, the single
+    per-tick claim_decision line must name the selected fid AND why the higher card
+    was passed over — the evidence to tell the hot-file guard from a lost claim race.
+    Mirrors the caplog pattern in test_store.test_run_logs_the_retry_count_on_final_success."""
+    # bd-hi is FIRST in the ready queue (higher priority) but collides on shared.py with
+    # an in-flight build; bd-lo is disjoint and gets claimed ahead of it.
+    store = _ClaimStore([_ready("bd-hi", ["shared.py"]), _ready("bd-lo", ["other.py"])])
+    monkeypatch.setattr("project_board.loop.get_store", lambda **_kw: store)
+    loop = BoardLoop({"max_concurrent": 2})
+    loop._inflight_files = {"bd-live": {"shared.py"}}  # an in-flight build already owns shared.py
+    finish = await _hold_drives(loop, monkeypatch)
+    try:
+        with caplog.at_level("INFO", logger="protoagent.plugins.project_board"):
+            loop._spawn_ready()
+    finally:
+        await finish()
+    assert store.claimed == ["bd-lo"]  # the lower-priority card claimed ahead of bd-hi
+    lines = [m for m in caplog.messages if "claim_decision" in m]
+    assert len(lines) == 1  # exactly one structured line per tick
+    payload = json.loads(lines[0].split("claim_decision", 1)[1])  # parseable without log grepping
+    assert payload["selected"] == ["bd-lo"]  # the selected fid is recorded
+    skip = {s["fid"]: s for s in payload["skipped"]}
+    assert skip["bd-hi"]["reason"] == "hot-file"  # the passed-over card's reason…
+    assert skip["bd-hi"]["overlaps"] == ["bd-live"]  # …names the in-flight build it collides with
+    assert skip["bd-hi"]["files"] == ["shared.py"]
+
+
+async def test_spawn_ready_logs_a_claim_race_skip(monkeypatch, caplog):
+    """#124: a candidate whose claim() returns None (lost the atomic-claim race) is
+    recorded with a distinct, parseable reason — not conflated with the hot-file guard."""
+
+    class _RacingStore(_ClaimStore):
+        def claim(self, fid, assignee=""):
+            if fid == "bd-hi":
+                return None  # someone else won the claim race for the higher card
+            return super().claim(fid, assignee=assignee)
+
+    store = _RacingStore([_ready("bd-hi", ["a.py"]), _ready("bd-lo", ["b.py"])])
+    monkeypatch.setattr("project_board.loop.get_store", lambda **_kw: store)
+    loop = BoardLoop({"max_concurrent": 2})
+    finish = await _hold_drives(loop, monkeypatch)
+    try:
+        with caplog.at_level("INFO", logger="protoagent.plugins.project_board"):
+            loop._spawn_ready()
+    finally:
+        await finish()
+    lines = [m for m in caplog.messages if "claim_decision" in m]
+    assert len(lines) == 1
+    payload = json.loads(lines[0].split("claim_decision", 1)[1])
+    assert payload["selected"] == ["bd-lo"]
+    skip = {s["fid"]: s for s in payload["skipped"]}
+    assert skip["bd-hi"]["reason"] == "claim-race"
+
+
 # ── the PR reconcile (terminal-edge fallback) ───────────────────────────────────