From c7ccffa1d4367bf24e466b9f3d9f0b28ec8efda2 Mon Sep 17 00:00:00 2001 From: drknowhow Date: Tue, 8 Sep 2026 14:13:09 -0400 Subject: [PATCH] fix(sessions): rare-event scan window and per-project hook paths (2.128.1) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both found by shipping 2.128.0 and watching the runtime, not by a test. A busy activity log hid the running session. ProjectManager looked up the rare rows liveness depends on (session_start, session_save, session_end) with ActivityLog.get_recent(limit=1, event_type=...), which scans only the last limit*100 lines. That window is minutes wide on a working project: right after 2.128.0 went live, this repo had its RUNNING session's session_start sitting 319 lines from the end of a 20,825-line log and get_recent returned [] — so the hub called an actively-served project idle and the 20-minute rule was never even reached. It predates 2.128.0 by a long way and is the other half of "the live light is wrong". - ActivityLog.find_last(event_type, limit=1) scans backwards in 256 KB chunks, stitching lines across boundaries, and stops at the first match. It finds the row however much traffic is in front of it, and it is faster than the call it replaces (0.9 ms vs 6.4 ms on that 4.9 MB log) because it stops instead of reading the whole file. - ProjectManager._rare_rows routes every rare-event lookup through it and falls back to get_recent when the object has no find_last — a test stub, or an older C3 in another checkout serving the same project. _get_last_session_timestamp now also considers session_end. The hook migration wrote its own install path into a checkout. The hub runs from wherever C3 is installed, so it built every command from its cli/ directory. Right for the 59 projects on the installed C3; wrong for this repo, whose other hooks point at the working tree, where it would have made an edited hook a no-op until the next install — two sources of truth for one hook, invisible until something silently does not run. - detect_project_cli_dir(path) reads the project's settings, finds the cli/ its current C3 hooks use (a hook_*.py whose directory still holds hook_dispatch.py), and builds that project's entries against it. A path that no longer exists is ignored; a project with no C3 hooks falls back to the hub's own location. Each project gets its own table now. Tests: tests/test_activity_log_find_last.py (backwards scan, chunk boundaries, corrupt lines, missing file), migration cases for the detected and fallback cli_dir, and a liveness test over a real 500-row log. Full suite 4022 passed / 7 skipped; the one failure, tests/test_ci_act.py's act integration case (parser 'unparsed' != 'ruff'), reproduces on clean main and is unrelated — filed separately. Claude-Session: https://claude.ai/code/session_01FLzc3usUhbfdF9M35UUMb5 --- CHANGELOG.md | 44 +++++++++++++ cli/c3.py | 2 +- cli/hub_server.py | 54 +++++++++++++++- docs/session-liveness.md | 8 ++- pyproject.toml | 2 +- services/activity_log.py | 48 ++++++++++++++ services/project_manager.py | 46 ++++++++----- tests/test_activity_log_find_last.py | 96 ++++++++++++++++++++++++++++ tests/test_hub_hook_migration.py | 34 ++++++++++ tests/test_project_manager.py | 29 +++++++++ 10 files changed, 341 insertions(+), 22 deletions(-) create mode 100644 tests/test_activity_log_find_last.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 1aa84e9..1daa903 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,50 @@ All notable changes to Code Context Control (C3) are documented here. The format is loosely based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [2.128.1] - 2026-09-08 + +Both of these were found by shipping 2.128.0 and watching the runtime, not +by a test. + +### Fixed — a busy activity log hid the running session + +`ProjectManager` looked up the rare rows liveness depends on +(`session_start`, `session_save`, `session_end`) with +`ActivityLog.get_recent(limit=1, event_type=...)`, which scans only the last +`limit * 100` lines. That window is minutes wide on a working project: right +after 2.128.0 went live, C3's own repo had its **running** session's +`session_start` sitting **319 lines from the end of a 20,825-line log**, and +`get_recent` returned `[]` — so the hub called an actively-served project +idle. The 20-minute idle rule was never even reached. This is the other half +of "the live light is wrong", and it predates 2.128.0 by a long way. + +- **`ActivityLog.find_last(event_type, limit=1)`** — scans the log backwards + in 256 KB chunks and stops at the first `limit` matches, stitching lines + across chunk boundaries. It finds the row however much traffic is in front + of it, and it is *faster* than the old call on the same file (0.9 ms vs + 6.4 ms on that 4.9 MB log) because it stops instead of reading everything. +- **`ProjectManager._rare_rows`** routes every rare-event lookup through it, + falling back to `get_recent` when the object has no `find_last` — a test + stub, or an older C3 in another checkout serving the same project. + `_get_last_session_timestamp` now also considers `session_end`. + +### Fixed — the hook migration wrote its own install path into a checkout + +The hub runs from wherever C3 is installed, so `_migrate_project_hooks` built +every command from *its* `cli/` directory. For the 59 projects that use the +installed C3 that is right; for C3's own repo — whose other hooks point at the +working tree, because that is what a developer edits — it wrote site-packages +paths, which would have made an edited hook a no-op until the next install. +Two sources of truth for one hook, the failure mode that is invisible until +something silently does not run. + +- **`detect_project_cli_dir(path)`** reads the project's existing settings, + finds the `cli/` directory its current C3 hooks point at (a `hook_*.py` + whose directory still holds `hook_dispatch.py`), and builds that project's + entries against it. A path that no longer exists is ignored, and a project + with no C3 hooks yet falls back to the hub's own location. Each project now + gets its own table rather than one shared across all of them. + ## [2.128.0] - 2026-09-08 ### Fixed — starting an IDE session now brings up that project's UI diff --git a/cli/c3.py b/cli/c3.py index d74ef75..7858f8e 100644 --- a/cli/c3.py +++ b/cli/c3.py @@ -91,7 +91,7 @@ # Config CONFIG_DIR = ".c3" CONFIG_FILE = ".c3/config.json" -__version__ = "2.128.0" +__version__ = "2.128.1" def _compress_file_cli(compressor, path, mode="smart", **kw): diff --git a/cli/hub_server.py b/cli/hub_server.py index dbf618e..b894a0f 100644 --- a/cli/hub_server.py +++ b/cli/hub_server.py @@ -4447,6 +4447,52 @@ def _lifecycle(event: str, arg: str) -> dict: ] +def _command_cli_dir(command: str) -> Path | None: + """The C3 ``cli/`` directory a hook command points at, if any.""" + try: + tokens = shlex.split(str(command or ""), posix=False) + except ValueError: + tokens = str(command or "").split() + for token in tokens: + token = token.strip("'\"") + if not token.endswith(".py"): + continue + candidate = Path(token) + if not candidate.name.startswith("hook_"): + continue + parent = candidate.parent + if (parent / "hook_dispatch.py").is_file(): + return parent + return None + + +def detect_project_cli_dir(path: str) -> Path | None: + """The ``cli/`` directory this project's existing C3 hooks already use. + + The hub runs from wherever C3 is installed, so building commands from its + own location writes install paths into a project that was installed from a + checkout — C3's own repo above all, where the working tree IS the runtime. + A hook edited there would then change nothing until the next install. Match + what the project already points at; the caller falls back to ours. + """ + for rel_settings in (".claude/settings.local.json", ".gemini/settings.json"): + settings_path = Path(path) / rel_settings + if not settings_path.exists(): + continue + try: + with open(settings_path, encoding="utf-8") as f: + hooks = (json.load(f).get("hooks") or {}) + except Exception: + continue + for entries in hooks.values(): + for entry in entries or []: + for hook in (entry or {}).get("hooks", []): + found = _command_cli_dir((hook or {}).get("command") or "") + if found is not None: + return found + return None + + def migrate_hooks_for_project(path: str, migrations: list | None = None) -> int: """Apply the hook table to one project. Returns settings files changed. @@ -4454,7 +4500,8 @@ def migrate_hooks_for_project(path: str, migrations: list | None = None) -> int: ``.claude/settings.local.json`` has not been installed for Claude, and the hub is not the place to decide that it should be. """ - migrations = migrations if migrations is not None else c3_hook_migrations() + if migrations is None: + migrations = c3_hook_migrations(detect_project_cli_dir(path)) by_file: dict = {} for migration in migrations: by_file.setdefault(migration["settings"], []).append(migration) @@ -4500,13 +4547,14 @@ def _migrate_project_hooks(): except Exception: return - migrations = c3_hook_migrations() updated = 0 for p in projects: path = p.get("path", "") if not path: continue - updated += migrate_hooks_for_project(path, migrations) + # No shared table: each project's entries are built against the cli_dir + # that project's existing C3 hooks already point at. + updated += migrate_hooks_for_project(path) if updated: logging.getLogger(__name__).info( diff --git a/docs/session-liveness.md b/docs/session-liveness.md index 380ed0a..a775d0f 100644 --- a/docs/session-liveness.md +++ b/docs/session-liveness.md @@ -52,7 +52,13 @@ cleanup). Its two failure modes are the reason the heartbeat exists: - **a quiet session read dead** — no tool call for 20 minutes meant "gone", even with the MCP process right there. A fresh heartbeat now outranks any amount of silence, and it also outranks a `session_save`: the process is - still serving, and a bookkeeping row does not kill it. + still serving, and a bookkeeping row does not kill it; +- **a busy session read dead too**, for the opposite reason — the lookup used + `get_recent(limit=1, event_type=...)`, which scans only the last 100 lines + of the log. In this repo the running session's `session_start` sat 319 lines + from the end of a 20,825-line log, so nothing was found at all. Rare-event + lookups go through `ActivityLog.find_last` since 2.128.1, which scans + backwards until it finds the row (and is faster than the call it replaced). ## The UI follows the session diff --git a/pyproject.toml b/pyproject.toml index d5b6941..d0e66b7 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "code-context-control" -version = "2.128.0" +version = "2.128.1" description = "Local MCP code-intelligence for AI coding tools: surgical search/read/edit, agent-config version history, path-level access + masking guards, and a multi-project hub." readme = "README.md" requires-python = ">=3.10" diff --git a/services/activity_log.py b/services/activity_log.py index c12f619..99eaf11 100644 --- a/services/activity_log.py +++ b/services/activity_log.py @@ -58,6 +58,54 @@ def _maybe_rotate(self) -> None: except Exception: pass + def find_last(self, event_type: str, limit: int = 1, + chunk_bytes: int = 256 * 1024) -> list: + """Last N events of one type, however far back they are. + + ``get_recent`` only ever looks at the last ``limit * 100`` lines. For a + rare event in a busy log that window is minutes wide: in C3's own repo + the running session's ``session_start`` sat 319 lines from the end of a + 20,825-line log, so every liveness lookup missed it and the project + reported idle while a session was serving. Liveness must not depend on + how chatty the session has been since it started. + + Reads backwards in chunks and stops at the first ``limit`` matches, so + the common case (the row is near the end) touches one chunk instead of + the whole file. Newest first, like ``get_recent``. + """ + if not self.log_file.exists(): + return [] + events: list = [] + try: + with open(self.log_file, "rb") as handle: + handle.seek(0, 2) + position = handle.tell() + tail = b"" + while position > 0 and len(events) < limit: + step = min(chunk_bytes, position) + position -= step + handle.seek(position) + block = handle.read(step) + tail + lines = block.split(b"\n") + # The first element may be a partial line: keep it for the + # next (earlier) chunk unless we are at the file start. + tail = lines.pop(0) if position > 0 else b"" + for raw in reversed(lines): + if not raw.strip(): + continue + try: + entry = json.loads(raw.decode("utf-8", "replace")) + except (json.JSONDecodeError, UnicodeDecodeError): + continue + if entry.get("type") != event_type: + continue + events.append(entry) + if len(events) >= limit: + break + except OSError: + return events + return events + def get_recent(self, limit: int = 100, event_type: str = None, since: str = None, until: str = None) -> list: """Read last N events, optionally filtered by type and time range. diff --git a/services/project_manager.py b/services/project_manager.py index b28ba38..9d84102 100644 --- a/services/project_manager.py +++ b/services/project_manager.py @@ -144,6 +144,29 @@ def _get_budget_info(self, path: str) -> dict | None: pass return None + def _rare_rows(self, activity, event_type: str, limit: int = 1) -> list: + """Newest rows of a RARE type, whatever the traffic in front of them. + + ``get_recent`` scans only the last ``limit * 100`` lines, so on a busy + project a session's own ``session_start`` falls out of the window + within minutes — 319 lines from the end of a 20,825-line log in C3's + own repo — and every liveness lookup here saw nothing. + ``ActivityLog.find_last`` scans backwards until it finds the row. + + The ``get_recent`` fallback keeps test stubs and older ActivityLog + copies (another checkout serving the same project) working. + """ + finder = getattr(activity, "find_last", None) + if callable(finder): + try: + return finder(event_type, limit=limit) or [] + except Exception: + pass + try: + return activity.get_recent(limit=limit, event_type=event_type) or [] + except Exception: + return [] + def _ended_session_ids(self, activity, limit: int = 8) -> set: """Ids (C3 and host) of sessions with a terminal row in the log. @@ -154,11 +177,7 @@ def _ended_session_ids(self, activity, limit: int = 8) -> set: """ ended = set() for event_type in ("session_save", "session_end"): - try: - rows = activity.get_recent(limit=limit, event_type=event_type) or [] - except Exception: - rows = [] - for row in rows: + for row in self._rare_rows(activity, event_type, limit): for key in ("session_id", "host_session_id"): value = str(row.get(key) or "").strip() if value: @@ -206,14 +225,9 @@ def _get_live_sessions(self, path: str) -> list: sessions = [] seen = set() - # Typed get_recent scans 100x its limit, so these few rows reach well - # back past the tool_call traffic between them. - starts = [] - if beats: - try: - starts = activity.get_recent(limit=8, event_type="session_start") or [] - except Exception: - starts = [] + # Only to decorate the heartbeats with what the log knows (start time, + # description). A heartbeat with no matching row is still a session. + starts = self._rare_rows(activity, "session_start", 8) if beats else [] for beat in beats: session_id = str(beat.get("session_id") or "") host_sid = str(beat.get("host_session_id") or "") @@ -276,7 +290,7 @@ def _infer_live_session(self, path: str, activity=None) -> dict | None: # Use the public API — get_recent's scan_factor=100 for typed queries # handles sparse rare events (session_start can sit far behind many # tool_call entries). Going through the API also lets tests stub it. - starts = activity.get_recent(limit=1, event_type="session_start") + starts = self._rare_rows(activity, "session_start", 1) last_start = starts[0] if starts else None if last_start is None: @@ -336,8 +350,8 @@ def remember(value: str | None): remember(live_session.get("started_at")) try: activity = ActivityLog(path) - remember((activity.get_recent(limit=1, event_type="session_save") or [{}])[0].get("timestamp")) - remember((activity.get_recent(limit=1, event_type="session_start") or [{}])[0].get("timestamp")) + for event_type in ("session_save", "session_end", "session_start"): + remember((self._rare_rows(activity, event_type, 1) or [{}])[0].get("timestamp")) except Exception: pass return latest_raw diff --git a/tests/test_activity_log_find_last.py b/tests/test_activity_log_find_last.py new file mode 100644 index 0000000..734fcb7 --- /dev/null +++ b/tests/test_activity_log_find_last.py @@ -0,0 +1,96 @@ +"""ActivityLog.find_last — rare events behind heavy traffic (v2.128.1). + +`get_recent` scans only the last `limit * 100` lines. A session's own +`session_start` row falls out of that window within minutes of ordinary tool +use — measured at 319 lines from the end of C3's own 20,825-line log, where +`get_recent(limit=1, event_type="session_start")` returned nothing while the +session was running, so the hub reported the project idle. +""" +from __future__ import annotations + +import json +import sys +import tempfile +import unittest +from pathlib import Path + +REPO_ROOT = Path(__file__).resolve().parent.parent +sys.path.insert(0, str(REPO_ROOT)) + +from services.activity_log import ActivityLog # noqa: E402 + + +class TestFindLast(unittest.TestCase): + def setUp(self): + self.tmp = tempfile.TemporaryDirectory() + self.addCleanup(self.tmp.cleanup) + self.project = Path(self.tmp.name) + self.log = self.project / ".c3" / "activity_log.jsonl" + self.log.parent.mkdir(parents=True) + self.activity = ActivityLog(str(self.project)) + + def _write(self, rows): + self.log.write_text( + "".join(json.dumps(r) + "\n" for r in rows), encoding="utf-8") + + def _buried(self, noise: int): + rows = [{"type": "session_start", "session_id": "s1", "timestamp": "t0"}] + rows += [{"type": "tool_call", "timestamp": f"t{i}"} for i in range(noise)] + self._write(rows) + + def test_finds_a_row_get_recent_cannot_see(self): + self._buried(5000) + self.assertEqual(self.activity.get_recent(limit=1, event_type="session_start"), []) + found = self.activity.find_last("session_start") + self.assertEqual([r["session_id"] for r in found], ["s1"]) + + def test_row_near_the_end_still_works(self): + self._buried(3) + self.assertEqual(len(self.activity.find_last("session_start")), 1) + + def test_newest_first_and_limited(self): + self._write([ + {"type": "session_start", "session_id": "old", "timestamp": "t0"}, + {"type": "tool_call", "timestamp": "t1"}, + {"type": "session_start", "session_id": "mid", "timestamp": "t2"}, + {"type": "session_start", "session_id": "new", "timestamp": "t3"}, + ]) + self.assertEqual( + [r["session_id"] for r in self.activity.find_last("session_start", limit=2)], + ["new", "mid"]) + + def test_absent_type_and_missing_file(self): + self._buried(10) + self.assertEqual(self.activity.find_last("session_end"), []) + self.log.unlink() + self.assertEqual(self.activity.find_last("session_start"), []) + + def test_survives_a_corrupt_line(self): + self.log.write_text( + "{not json\n" + + json.dumps({"type": "session_start", "session_id": "s1"}) + "\n" + + "\n" + + json.dumps({"type": "tool_call"}) + "\n", + encoding="utf-8") + self.assertEqual( + [r["session_id"] for r in self.activity.find_last("session_start")], ["s1"]) + + def test_row_split_across_a_chunk_boundary(self): + """The backwards reader stitches partial lines between chunks.""" + rows = [{"type": "session_start", "session_id": "s1", "timestamp": "t0"}] + rows += [{"type": "tool_call", "payload": "x" * 200} for _ in range(2000)] + self._write(rows) + for chunk in (64, 128, 4096): + with self.subTest(chunk=chunk): + found = self.activity.find_last("session_start", chunk_bytes=chunk) + self.assertEqual([r["session_id"] for r in found], ["s1"]) + + def test_matches_get_recent_when_both_can_see_the_row(self): + self._buried(20) + self.assertEqual( + self.activity.find_last("session_start"), + self.activity.get_recent(limit=1, event_type="session_start")) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_hub_hook_migration.py b/tests/test_hub_hook_migration.py index 870510c..7bee3d8 100644 --- a/tests/test_hub_hook_migration.py +++ b/tests/test_hub_hook_migration.py @@ -128,6 +128,40 @@ def test_commands_are_quoted_for_this_platform(self): self.assertNotIn("'", command, command) self.assertNotIn("\\", command, command) + def test_new_entries_follow_the_project_s_existing_c3_install(self): + """The hub runs from site-packages; C3's own repo runs its hooks from + the checkout. Writing the hub's path into that project would make an + edited hook a no-op until the next install.""" + checkout_cli = self.project / "checkout" / "cli" + checkout_cli.mkdir(parents=True) + (checkout_cli / "hook_dispatch.py").write_text("", encoding="utf-8") + existing = f'"{sys.executable}" "{checkout_cli / "hook_dispatch.py"}" stop' + self._write(CLAUDE_SETTINGS, {"hooks": {"Stop": [ + {"matcher": "", "hooks": [{"type": "command", "command": existing}]}]}}) + self._migrate() + commands = self._commands(self._read(CLAUDE_SETTINGS), "SessionStart") + self.assertTrue(commands) + expected = str(checkout_cli).replace("\\", "/") + for command in commands: + self.assertIn(expected, command.replace("\\", "/")) + + def test_falls_back_to_the_hubs_own_cli_dir(self): + self._write(CLAUDE_SETTINGS, {"hooks": {}}) + self._migrate() + cli_dir = Path(hub_server.__file__).resolve().parent + for command in self._commands(self._read(CLAUDE_SETTINGS), "SessionStart"): + self.assertIn(cli_dir.name, command) + + def test_a_dead_install_path_is_not_followed(self): + """An old entry pointing at a cli/ that no longer exists is ignored.""" + gone = self.project / "uninstalled" / "cli" / "hook_dispatch.py" + self._write(CLAUDE_SETTINGS, {"hooks": {"Stop": [{"matcher": "", "hooks": [ + {"type": "command", "command": f'"{sys.executable}" "{gone}" stop'}]}]}}) + self._migrate() + commands = self._commands(self._read(CLAUDE_SETTINGS), "SessionStart") + self.assertTrue(commands) + self.assertNotIn("uninstalled", commands[0]) + def test_dispatcher_command_matches_the_installer_exactly(self): from cli._hook_utils import hook_command_arg cli_dir = Path(hub_server.__file__).resolve().parent diff --git a/tests/test_project_manager.py b/tests/test_project_manager.py index 81699ec..1405822 100644 --- a/tests/test_project_manager.py +++ b/tests/test_project_manager.py @@ -200,6 +200,35 @@ def test_session_end_matches_on_host_id_alone(self): "timestamp": recent}, ]), []) + def test_a_busy_log_no_longer_hides_the_running_session(self): + """Traffic since the session started used to make it invisible. + + `get_recent(limit=1, event_type=...)` looks at the last 100 lines only; + in C3's own repo the running session's `session_start` sat 319 lines + from the end, so the hub called an active project idle. Uses the real + ActivityLog — the point is the file scan, not the stub. + """ + log = Path(self.proj_path) / ".c3" / "activity_log.jsonl" + log.parent.mkdir(parents=True, exist_ok=True) + rows = [{"type": "session_start", "session_id": "s1", + "timestamp": self._ago(minutes=30), "description": "busy"}] + rows += [{"type": "tool_call", "timestamp": self._ago(seconds=30)} + for _ in range(500)] + log.write_text("".join(json.dumps(r) + "\n" for r in rows), encoding="utf-8") + sessions = self.pm._get_live_sessions(self.proj_path) + self.assertEqual([s["session_id"] for s in sessions], ["s1"]) + self.assertEqual(sessions[0]["source"], "activity_log") + self.assertEqual(sessions[0]["description"], "busy") + + def test_stub_without_find_last_still_works(self): + """Another checkout on an older C3 keeps serving the same project.""" + sessions = self._sessions([ + {"type": "session_start", "session_id": "s1", "timestamp": self._ago(minutes=5)}, + {"type": "tool_call", "timestamp": self._ago(minutes=1)}, + ]) + self.assertFalse(hasattr(_StubActivityLog([]), "find_last")) + self.assertEqual([s["session_id"] for s in sessions], ["s1"]) + # ── heartbeats outrank inference ────────────────────────────────────── def test_heartbeat_keeps_a_long_idle_session_live(self):