← Commit history

0.9.349: kicad_status carries operation state for timeout recovery (#87)

John Lauer ·44395ac3b4 ·1mo ago ·parent 7235d28
2 files changed +72−6
handlers/progress.py+38−3
@@ -368,10 +368,12 @@ def _runlog_path() -> Path:     return _path().parent / "kicad-verb-times.jsonl"  -def log_run(verb: str, seconds: float, ok: bool = True, note: str = "") -> None:+def log_run(verb: str, seconds: float, ok: bool = True, note: str = "", caller: str = None) -> None:     """Append one verb run to the historical log AND the rolling window.     Called at the dispatch chokepoint for EVERY verb - one wrapper, not-    per-verb calls someone forgets. Never raises."""+    per-verb calls someone forgets. Never raises. `caller` and `note` (the+    error text of a failed run) make the log answer #87: "did MY operation+    finish, and how?" from kicad_status after a timeout."""     try:         seconds = float(seconds)         if seconds < 0 or seconds > 7200:@@ -386,11 +388,44 @@ def log_run(verb: str, seconds: float, ok: bool = True, note: str = "") -> None:         with open(p, "a", encoding="utf-8") as f:             f.write(json.dumps({"at": int(time.time()), "verb": verb,                                 "seconds": round(seconds, 2),-                                "ok": bool(ok), "note": (note or "")[:120]}) + "\n")+                                "ok": bool(ok), "note": (note or "")[:120],+                                "caller": (caller or _caller())[:80]}) + "\n")     except Exception:         pass  +def recent(limit: int = 10, caller: str = None) -> list:+    """The last `limit` finished runs, newest first, optionally one caller's.++    This is the terminal-result surface kicad_status hands a poller after ab's+    130 s budget ran out (#87): each row says which verb, when it finished,+    how long it took, whether it succeeded, and the error text when not."""+    rows = []+    try:+        p = _runlog_path()+        if not p.exists():+            return []+        with open(p, "rb") as f:+            f.seek(0, 2)+            size = f.tell()+            f.seek(max(0, size - 64 * 1024))+            tail = f.read().decode("utf-8", "replace")+        for line in tail.splitlines():+            try:+                r = json.loads(line)+            except Exception:+                continue+            if caller and r.get("caller") != caller:+                continue+            rows.append({"verb": r.get("verb"), "finishedAt": r.get("at"),+                         "seconds": r.get("seconds"), "ok": bool(r.get("ok")),+                         "error": (r.get("note") or None) if not r.get("ok") else None,+                         "caller": r.get("caller")})+    except Exception:+        return rows+    return list(reversed(rows))[:limit]++ def verb_report(limit: int = 40) -> dict:     """Aggregate the historical log: per verb count / p50 / p90 / max / failures,     sorted by p90 descending - p90, not p50, is the column for hunting slow
server.py+34−3
@@ -582,7 +582,7 @@ _VERB_CATALOG = {         "hint": "Read-only; lists live in-process plugin instances + their ports/health. Bounded, non-blocking.",         "related": ["kicad_bridge_call", "kicad_open_editors", "kicad_install_plugin"], "pitfalls": ["an instance shows only after KiCad has run a kicad_* call that loaded the plugin"]},     "status": {"summary": "Bridge/host-app status — the verb Bridge polls after a non-terminal timeout.", "long": False,-        "hint": "Canonical statusVerb (see bridge.json). Read-only; poll this after a long verb returns {stillRunning:true} to check whether it finished.",+        "hint": "Canonical statusVerb (see bridge.json). Read-only. After a long verb returns {stillRunning:true}, poll this: operations.yours.recent lists your finished verbs with ok/error and finishedAt, operations.yours.active the ones still running with stepLabel/percent; plugins[] is liveness only.",         "related": ["kicad_readiness", "kicad_bridge_status"], "pitfalls": ["reports bridge + plugin liveness, not per-export progress"]},     "bridge_call": {"summary": "Call into a running KiCad plugin instance (in-process IPC).", "long": False,         "hint": "Low-level IPC into a live pcbnew/eeschema; use bridge_status first to find a live instance.",@@ -874,6 +874,35 @@ def _handle_verb_times(kicad_info: dict, args: dict) -> dict:                       "pass. The rolling estimate window is separate; kicad_progress and "                       "the progress blocks draw from that.")} +def _handle_status(kicad_info: dict, args: dict) -> dict:+    """kicad_status: the manifest's statusVerb, so it must answer the question a+    poller has after ab's budget ran out: did my operation finish, and how?+    (#87: it used to be plugin inventory only.) Plugin liveness stays; on top of+    it `operations` carries every phase in flight (all callers, each frame named)+    and the last finished runs with their outcome, plus `yours` for the caller."""+    out = handle_bridge_status(kicad_info, args)+    try:+        from handlers import progress as _pg+        me = _pg._caller()+        active = _pg.live(mine_only=False)+        recent_all = _pg.recent(limit=int((args or {}).get("recent") or 10))+        recent_mine = [r for r in recent_all if r.get("caller") == me]+        out["operations"] = {+            "active": active,+            "recent": recent_all,+            "yours": {"active": [a for a in active if a.get("caller") == me], "recent": recent_mine},+            "busy": bool(active),+        }+        out["_operationsHint"] = (+            "After a timeout: look for your verb in operations.yours.recent (ok/error, finishedAt) or "+            "operations.yours.active (still running, with stepLabel/percent). Not there yet means still "+            "running or never started: keep polling; do not resend a mutation blindly. "+            "kicad_progress is the same live view with ETAs; plugins[] below is liveness, not progress.")+    except Exception as exc:  # pylint: disable=broad-except+        out["operations"] = {"error": str(exc)[:120]}+    return out++ def _handle_progress(kicad_info: dict, args: dict) -> dict:     """kicad_progress — what is this bridge doing RIGHT NOW, as progress blocks. @@ -1018,7 +1047,7 @@ COMMAND_HANDLERS = {     # kicad_status: the canonical statusVerb Bridge polls after a non-terminal timeout     # (bridge.json `statusVerb` + detect.hostAppOptionalVerbs "status"). Alias of     # bridge_status; kicad_bridge_status stays for back-compat.-    "status": handle_bridge_status,+    "status": _handle_status,     "bridge_call": handle_bridge_call,     "open_editors": handle_open_editors,     "launch": handle_launch,@@ -1340,7 +1369,9 @@ def dispatch_command(command: str, args: dict) -> dict:             # the first cut here logged it as ok=True. An exception and a             # success:false both count as failed runs in the log.             _ok = isinstance(_res, dict) and _res.get("success") is not False-            _pgT.log_run(command, time.time() - _prog_started, ok=bool(_ok))+            _note = "" if _ok else (str((_res or {}).get("error") or (_res or {}).get("errorCode") or "handler raised")+                                    if isinstance(_res, dict) else "handler raised")+            _pgT.log_run(command, time.time() - _prog_started, ok=bool(_ok), note=_note)         except Exception:             pass         # The taskbar activity indicator pairs with note_driving: the bar must