From 73f4a432e4ac1d575635a490d96e0f5ea588344d Mon Sep 17 00:00:00 2001 From: Martin Vogel Date: Thu, 3 Sep 2026 14:56:42 +0200 Subject: [PATCH] test(windows): isolate the daemon guards' rendezvous and stop hiding their failures Every Windows guard shared ONE daemon. test_daemon_stability.py said each section "runs under its OWN cache directory: daemon coordination is cache-scoped" -- it is not. The rendezvous key is FNV-1a over a compile-time domain string (service.c: cbm_daemon_rendezvous_key) under a machine-global parent (win_default_runtime_parent -> SHGetFolderPathW(CSIDL_LOCAL_APPDATA), which ignores the LOCALAPPDATA variable). So the guard's own `daemon stop` and kill -9 sections, the sibling guards, and anything else on the runner all met the same daemon, and a daemon wedged anywhere failed every check after it. That is the shape of this week's test-windows-guards red on #1874: lifecycle's `daemon start` connected, the UI-config handshake never answered, and stability / hook_augment / ui_drive / cli_non_ascii went red in a row with an orphan daemon killed at cleanup -- on a diff and a base that were each green elsewhere. CBM_RUNTIME_DIR is the only relocation hook (bootstrap.c, resolved in cbm_daemon_bootstrap_endpoint_new for every product endpoint). Each stability section now gets a private runtime parent next to its cache, created before the binary runs -- the endpoint validates the parent and never creates it -- and the daemon inherits it from the client that spawns it. Proven on macOS: a daemon on the default rendezvous keeps its pid across the whole guard (three stops and a kill -9 inside it). The reporting was hiding the cause as well: * every SETUP FAIL printed nothing at all, and every RED printed a 300-400 character HEAD slice, which is the allocator preamble, never the error. Excerpts now show the tail (1500 chars); setup paths print the daemon's full output. * a subprocess timeout raised on a parallel-client worker thread was lost and the client reported as "rc=none" with no output; it is now kept as a failed result with its partial output. A section-level timeout is a named RED with the command and output, not a bare traceback. * the MCP session's stderr went to DEVNULL; it now goes to a file that is printed when initialize never answers -- and that case is a RED against a running daemon, not a "setup" skip. * exit 2 was documented and never produced. Only `daemon start` failing raises it now (test_daemon_lifecycle.py owns that surface as a regression, so the board loses nothing); main() runs every section and names all of the failing ones. * test_hook_augment.py / test_cli_non_ascii_arg.py print full stdout AND stderr on their index-setup failures instead of 300 chars of stdout. On POSIX (local iteration only) the namespace lives under /tmp: sun_path caps the socket at 104 bytes on macOS and TMPDIR there is ~50 bytes deep. Out of scope, noted: test_daemon_lifecycle.py, test_non_ascii_path.py and test_ui_drive_listing.py still use the machine-global rendezvous; a too-long CBM_RUNTIME_DIR on POSIX is refused (ipc.c sun_path check) with no validation detail. Signed-off-by: Martin Vogel --- tests/windows/test_cli_non_ascii_arg.py | 14 +- tests/windows/test_daemon_stability.py | 205 +++++++++++++++++------- tests/windows/test_hook_augment.py | 12 +- 3 files changed, 168 insertions(+), 63 deletions(-) diff --git a/tests/windows/test_cli_non_ascii_arg.py b/tests/windows/test_cli_non_ascii_arg.py index f5180628e..037869aaa 100644 --- a/tests/windows/test_cli_non_ascii_arg.py +++ b/tests/windows/test_cli_non_ascii_arg.py @@ -73,6 +73,7 @@ def main(): # (#1952). One retry against a fresh cache separates that from a real # CLI indexing failure. ctrl_out = "" + ctrl_err = "" for attempt in ("cache_ascii", "cache_ascii_retry"): env = dict(os.environ) env["CBM_CACHE_DIR"] = os.path.join(work, attempt) @@ -81,14 +82,19 @@ def main(): json.dumps({"repo_path": ascii_repo})], capture_output=True, timeout=120, env=env) ctrl_out = (ctrl.stdout or b"").decode("utf-8", "replace") + ctrl_err = (ctrl.stderr or b"").decode("utf-8", "replace") if '"nodes"' in ctrl_out: break - print("SETUP: ASCII control attempt %r did not index via CLI:\n%s" - % (attempt, ctrl_out[:300])) + # Full stdout AND stderr: the reason lives on stderr (daemon + # spawn/handshake diagnostics), and a head slice of stdout only + # ever showed the allocator preamble. + print("SETUP: ASCII control attempt %r did not index via CLI (rc=%s):\n" + "stdout:\n%s\nstderr:\n%s" + % (attempt, ctrl.returncode, ctrl_out, ctrl_err)) time.sleep(2) if '"nodes"' not in ctrl_out: - print("SETUP FAIL: ASCII control did not index via CLI:\n%s" % - ctrl_out[:300]) + print("SETUP FAIL: ASCII control did not index via CLI:\nstdout:\n%s\nstderr:\n%s" + % (ctrl_out, ctrl_err)) return 2 env2 = dict(os.environ) diff --git a/tests/windows/test_daemon_stability.py b/tests/windows/test_daemon_stability.py index dbe496fef..43b96723b 100644 --- a/tests/windows/test_daemon_stability.py +++ b/tests/windows/test_daemon_stability.py @@ -24,10 +24,22 @@ Every daemon this guard starts carries a kill-by-pid backstop so a stuck daemon can never hang the suite. Each section runs under its OWN cache -directory: daemon coordination is cache-scoped, so sections are isolated from -each other and from any interactive CBM use on the host. - -Exit code: 0 == all sections green, 1 == regression, 2 == setup error. +directory AND its own ``CBM_RUNTIME_DIR``; the second one is what isolates it. +Daemon coordination is NOT cache-scoped: the rendezvous key hashes a +compile-time constant under a machine-global parent (the real +``CSIDL_LOCAL_APPDATA`` -- the ``LOCALAPPDATA`` variable is ignored), so +without the override every section, every sibling guard on the runner and +any interactive CBM use on the host share ONE daemon, and a daemon wedged in +one place fails every check that comes after it. ``CBM_RUNTIME_DIR`` is the +only relocation hook; the daemon inherits it from the client that spawns it, +and the directory must exist before the binary runs because the endpoint +code validates the parent and never creates it. + +Exit code: 0 == all sections green; 1 == regression (every failing section is +named -- sections are isolated, so a red one no longer poisons the rest); +2 == setup error: a precondition the lifecycle guard owns -- ``daemon start`` +itself -- did not hold. The daemon's FULL output is printed either way, so the +board shows why instead of a 300-character allocator preamble. Usage: python test_daemon_stability.py @@ -44,19 +56,63 @@ import time STATUS_POLL_S = 0.5 +# Failure excerpts show the TAIL of the output: the allocator/runtime preamble +# comes first, and a fixed head slice used to hide the actual error. +EXCERPT_CHARS = 1500 +# Return code reported for a client that hit its subprocess timeout. +TIMEOUT_RC = 124 -def run_cli(binary, cache, args, stdin=None, timeout=90): +class SetupFailure(Exception): + """A precondition this guard does not own did not hold. + + Only ``daemon start`` failures raise this: test_daemon_lifecycle.py runs + first and asserts that surface as a regression, so reporting it here as + exit 2 (precondition) hides nothing from the board. Everything the guard + owns -- including an MCP session failing to initialize against a daemon + that DID start -- stays a regression (exit 1). + """ + + +def runtime_for(cache): + """The section's private daemon rendezvous parent, a sibling of its cache.""" + head, tail = os.path.split(cache) + return os.path.join(head, tail.replace("cache-", "runtime-", 1)) + + +def section_dirs(work, name): + cache = os.path.join(work, "cache-" + name) + os.makedirs(cache, exist_ok=True) + # Must exist before the binary runs: the endpoint validates the parent + # (exists, is a directory, not a reparse point) and never creates it. + os.makedirs(runtime_for(cache), exist_ok=True) + return cache + + +def cli_env(cache): env = dict(os.environ) env["CBM_CACHE_DIR"] = cache + env["CBM_RUNTIME_DIR"] = runtime_for(cache) + return env + + +def run_cli(binary, cache, args, stdin=None, timeout=90): return subprocess.run([binary] + args, capture_output=True, timeout=timeout, - env=env, input=stdin) + env=cli_env(cache), input=stdin) def out_text(result): return ((result.stdout or b"") + (result.stderr or b"")).decode("utf-8", "replace") +def excerpt(text, limit=EXCERPT_CHARS): + if isinstance(text, bytes): + text = text.decode("utf-8", "replace") + if len(text) <= limit: + return text + return "...(%d chars elided)...\n%s" % (len(text) - limit, text[-limit:]) + + def kill_pid(pid): if not pid: return @@ -97,28 +153,26 @@ def _reader(): def section_params(binary, work): - cache = os.path.join(work, "cache-params") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "params") bare = run_cli(binary, cache, ["daemon"]) if bare.returncode == 0 or "usage:" not in out_text(bare): - print("RED: bare `daemon` should print usage and fail:\n%s" % out_text(bare)[:300]) + print("RED: bare `daemon` should print usage and fail:\n%s" % excerpt(out_text(bare))) return False unknown = run_cli(binary, cache, ["daemon", "bogus"]) if unknown.returncode == 0 or "unknown daemon option" not in out_text(unknown): - print("RED: `daemon bogus` should be rejected:\n%s" % out_text(unknown)[:300]) + print("RED: `daemon bogus` should be rejected:\n%s" % excerpt(out_text(unknown))) return False bad_port = run_cli(binary, cache, ["daemon", "start", "--port=0"]) if bad_port.returncode == 0 or "--port requires" not in out_text(bad_port): print("RED: `--port=0` should be rejected before spawning:\n%s" - % out_text(bad_port)[:300]) + % excerpt(out_text(bad_port))) return False print("PASS: parameter surface rejects bare/unknown/out-of-range daemon invocations") return True def section_hook_fail_open(binary, work): - cache = os.path.join(work, "cache-hook") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "hook") payload = json.dumps({ "hook_event_name": "PreToolUse", "tool_name": "Grep", @@ -131,7 +185,7 @@ def section_hook_fail_open(binary, work): marker = os.path.join(cache, ".hook-daemon-absent-notice") if first.returncode != 0: print("RED: hook-augment without a daemon must fail OPEN (exit 0), got rc=%d:\n%s" - % (first.returncode, (first_out + first_err)[:300])) + % (first.returncode, excerpt(first_out + first_err))) return False if "systemMessage" not in first_out or "no CBM daemon" not in first_err: print("RED: the first absent-daemon hook call must surface the visible notice " @@ -152,8 +206,7 @@ def section_hook_fail_open(binary, work): def section_start_status_port(binary, work): - cache = os.path.join(work, "cache-start") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "start") daemon_pid = 0 blocker = socket.socket(socket.AF_INET, socket.SOCK_STREAM) try: @@ -165,21 +218,21 @@ def section_start_status_port(binary, work): daemon_pid = pid_from(start_text) if start.returncode != 0 or "permanent" not in start_text or not daemon_pid: print("RED: `daemon start --port=` must still start the daemon " - "(UI bind is non-blocking):\n%s" % start_text[:400]) + "(UI bind is non-blocking):\n%s" % excerpt(start_text)) return False status = run_cli(binary, cache, ["daemon", "status"]) status_text = out_text(status) if status.returncode != 0 or "active (permanent" not in status_text or \ pid_from(status_text) != daemon_pid: print("RED: status must report the active permanent daemon pid %d:\n%s" - % (daemon_pid, status_text[:400])) + % (daemon_pid, excerpt(status_text))) return False again = run_cli(binary, cache, ["daemon", "start"], timeout=60) again_text = out_text(again) if again.returncode != 0 or "already active (permanent" not in again_text or \ pid_from(again_text) != daemon_pid: print("RED: a second `daemon start` must report already-active with the SAME " - "pid %d:\n%s" % (daemon_pid, again_text[:400])) + "pid %d:\n%s" % (daemon_pid, excerpt(again_text))) return False stop = run_cli(binary, cache, ["daemon", "stop"]) if stop.returncode != 0 or not wait_status_not_running(binary, cache, 45): @@ -195,28 +248,36 @@ def section_start_status_port(binary, work): def section_stop_refuses_busy(binary, work): - cache = os.path.join(work, "cache-busy") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "busy") daemon_pid = 0 session = None + session_err = None try: start = run_cli(binary, cache, ["daemon", "start"], timeout=60) daemon_pid = pid_from(out_text(start)) if start.returncode != 0 or not daemon_pid: - print("SETUP FAIL: permanent daemon did not start for the busy-stop check") - return False - env = dict(os.environ) - env["CBM_CACHE_DIR"] = cache + raise SetupFailure("permanent daemon did not start for the busy-stop check " + "(rc=%s):\n%s" % (start.returncode, out_text(start))) + # The session's stderr goes to a file, not DEVNULL: when initialize + # never answers, it is the only trace of what the frontend saw. + session_err_path = os.path.join(work, "busy-session.stderr") + session_err = open(session_err_path, "wb") session = subprocess.Popen([binary], stdin=subprocess.PIPE, - stdout=subprocess.PIPE, stderr=subprocess.DEVNULL, - env=env) + stdout=subprocess.PIPE, stderr=session_err, + env=cli_env(cache)) session.stdin.write(b'{"jsonrpc":"2.0","id":0,"method":"initialize",' b'"params":{"capabilities":{}}}\n') session.stdin.flush() reply = read_line_with_timeout(session.stdout, 45) if not reply or b'"result"' not in reply: - print("SETUP FAIL: MCP session did not complete initialize: %r" - % (reply[:200] if reply else reply)) + session.kill() + session.wait(timeout=30) + session_err.close() + with open(session_err_path, "rb") as handle: + session_stderr = handle.read() + print("RED: MCP session did not complete initialize against a running " + "daemon (pid %d); reply=%r\nsession stderr:\n%s" + % (daemon_pid, reply, excerpt(session_stderr))) return False busy = run_cli(binary, cache, ["daemon", "stop"]) busy_text = out_text(busy) @@ -228,7 +289,7 @@ def section_stop_refuses_busy(binary, work): pids_ok = bool(listed_pids) if os.name == "nt" else str(session.pid) in listed_pids if busy.returncode == 0 or "NOT stopped" not in busy_text or not pids_ok: print("RED: `daemon stop` with an attached MCP session (pid %d) must refuse " - "and list the blocking client:\n%s" % (session.pid, busy_text[:400])) + "and list the blocking client:\n%s" % (session.pid, excerpt(busy_text))) return False session.stdin.close() session.wait(timeout=45) @@ -250,20 +311,21 @@ def section_stop_refuses_busy(binary, work): finally: if session and session.poll() is None: session.kill() + if session_err: + session_err.close() kill_pid(daemon_pid) def section_crash_recovery(binary, work): - cache = os.path.join(work, "cache-crash") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "crash") daemon_pid = 0 second_pid = 0 try: start = run_cli(binary, cache, ["daemon", "start"], timeout=60) daemon_pid = pid_from(out_text(start)) if start.returncode != 0 or not daemon_pid: - print("SETUP FAIL: permanent daemon did not start for the crash check") - return False + raise SetupFailure("permanent daemon did not start for the crash check " + "(rc=%s):\n%s" % (start.returncode, out_text(start))) kill_pid(daemon_pid) if not wait_status_not_running(binary, cache, 60): print("RED: after kill -9 of pid %d the stale daemon state never cleared " @@ -272,13 +334,13 @@ def section_crash_recovery(binary, work): cold = run_cli(binary, cache, ["cli", "list_projects", "{}"], timeout=90) if cold.returncode != 0 or "daemon start" not in out_text(cold): print("RED: a cold one-shot after the daemon crash should succeed with the " - "startup-tax hint:\n%s" % out_text(cold)[:400]) + "startup-tax hint:\n%s" % excerpt(out_text(cold))) return False restart = run_cli(binary, cache, ["daemon", "start"], timeout=60) second_pid = pid_from(out_text(restart)) if restart.returncode != 0 or not second_pid or second_pid == daemon_pid: print("RED: `daemon start` after the crash must launch a FRESH daemon:\n%s" - % out_text(restart)[:400]) + % excerpt(out_text(restart))) return False daemon_pid = 0 stop = run_cli(binary, cache, ["daemon", "stop"]) @@ -298,7 +360,16 @@ def _parallel_one_shots(binary, cache, count): results = [None] * count def _one(index): - results[index] = run_cli(binary, cache, ["cli", "list_projects", "{}"], timeout=120) + try: + results[index] = run_cli(binary, cache, ["cli", "list_projects", "{}"], + timeout=120) + except subprocess.TimeoutExpired as exc: + # Keep the hang as a failed result WITH its partial output; raised + # on the worker thread it was lost, and the client reported as + # "rc=none" with nothing to read. + results[index] = subprocess.CompletedProcess( + exc.cmd, TIMEOUT_RC, exc.stdout or b"", + (exc.stderr or b"") + ("\n[timed out after %ss]" % exc.timeout).encode()) threads = [threading.Thread(target=_one, args=(i,)) for i in range(count)] for thread in threads: @@ -309,37 +380,34 @@ def _one(index): def section_churn_stability(binary, work): - cache = os.path.join(work, "cache-churn") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "churn") daemon_pid = 0 try: start = run_cli(binary, cache, ["daemon", "start"], timeout=60) daemon_pid = pid_from(out_text(start)) if start.returncode != 0 or not daemon_pid: - print("SETUP FAIL: permanent daemon did not start for the churn check") - return False + raise SetupFailure("permanent daemon did not start for the churn check " + "(rc=%s):\n%s" % (start.returncode, out_text(start))) for round_index in range(10): one = run_cli(binary, cache, ["cli", "list_projects", "{}"], timeout=90) if one.returncode != 0: print("RED: sequential churn one-shot %d failed:\n%s" - % (round_index, out_text(one)[:300])) + % (round_index, excerpt(out_text(one)))) return False for wave in range(2): results = _parallel_one_shots(binary, cache, 6) for index, result in enumerate(results): if result is None or result.returncode != 0: - print("RED: parallel churn wave %d client %d failed (rc=%s):\n" - "stdout=%r\nstderr=%r" + print("RED: parallel churn wave %d client %d failed (rc=%s):\n%s" % (wave, index, - result.returncode if result else "none", - (result.stdout or b"")[-300:] if result else b"", - (result.stderr or b"")[-400:] if result else b"")) + result.returncode if result else "none (still running)", + excerpt(out_text(result)) if result else "(no result)")) return False status = run_cli(binary, cache, ["daemon", "status"]) status_text = out_text(status) if status.returncode != 0 or pid_from(status_text) != daemon_pid: print("RED: after the churn the daemon must still be the SAME process " - "(expected pid %d):\n%s" % (daemon_pid, status_text[:400])) + "(expected pid %d):\n%s" % (daemon_pid, excerpt(status_text))) return False stop = run_cli(binary, cache, ["daemon", "stop"]) if stop.returncode != 0 or not wait_status_not_running(binary, cache, 45): @@ -354,13 +422,12 @@ def section_churn_stability(binary, work): def section_cold_storm(binary, work): - cache = os.path.join(work, "cache-storm") - os.makedirs(cache, exist_ok=True) + cache = section_dirs(work, "storm") results = _parallel_one_shots(binary, cache, 6) for index, result in enumerate(results): if result is None or result.returncode != 0: print("RED: cold-storm client %d failed (racing daemon spawn):\n%s" - % (index, out_text(result)[:300] if result else "(no result)")) + % (index, excerpt(out_text(result)) if result else "(no result)")) return False if not wait_status_not_running(binary, cache, 90): print("RED: the ephemeral daemon shared by the cold storm never retired") @@ -378,7 +445,12 @@ def main(): print("FAIL: binary not found: %s" % binary) return 2 - work = tempfile.mkdtemp(prefix="cbm_daemon_stab_") + # POSIX is for local iteration only, and there the rendezvous is a Unix + # socket whose path is capped at 104 bytes on macOS (sun_path); the default + # TMPDIR is already ~50 bytes deep, so keep the whole namespace under /tmp. + # On Windows TEMP is the guard root the runner hardened; leave it alone. + work = tempfile.mkdtemp(prefix="cbm_daemon_stab_", + dir=None if os.name == "nt" else "/tmp") sections = [ section_params, section_hook_fail_open, @@ -388,12 +460,33 @@ def main(): section_churn_stability, section_cold_storm, ] + failed = [] + setup_failed = [] try: for section in sections: - if not section(binary, work): - print("\nRED (tests/windows/test_daemon_stability.py): %s failed" - % section.__name__) - return 1 + try: + ok = section(binary, work) + except SetupFailure as exc: + print("\nSETUP FAIL (%s): %s" % (section.__name__, exc)) + setup_failed.append(section.__name__) + continue + except subprocess.TimeoutExpired as exc: + # The section's own finally already fired its kill backstop. + print("\nRED: %s hung -- %s timed out after %ss:\n%s" + % (section.__name__, exc.cmd, exc.timeout, + excerpt((exc.stdout or b"") + (exc.stderr or b"")))) + ok = False + if not ok: + failed.append(section.__name__) + if failed: + print("\nRED (tests/windows/test_daemon_stability.py): %s failed" + % ", ".join(failed)) + return 1 + if setup_failed: + print("\nSETUP FAIL (tests/windows/test_daemon_stability.py): %s could not " + "run -- `daemon start` did not hold; the lifecycle guard owns that red" + % ", ".join(setup_failed)) + return 2 print("\nGREEN: daemon stability, parameters, and failure modes behave.") return 0 finally: diff --git a/tests/windows/test_hook_augment.py b/tests/windows/test_hook_augment.py index 98118338b..1f051e647 100644 --- a/tests/windows/test_hook_augment.py +++ b/tests/windows/test_hook_augment.py @@ -68,17 +68,23 @@ def main(): # coordination-daemon startup latency (#1952) is not misread as a # broken CLI index. Reindexing the same cache is idempotent. idx_out = "" + idx_err = "" for attempt in (1, 2): idx = run_cli(binary, cache, ["cli", "index_repository", json.dumps({"repo_path": repo_fwd})]) idx_out = (idx.stdout or b"").decode("utf-8", "replace") + idx_err = (idx.stderr or b"").decode("utf-8", "replace") if '"nodes"' in idx_out: break - print("SETUP: index attempt %d did not run:\n%s" - % (attempt, idx_out[:300])) + # Full stdout AND stderr: the reason lives on stderr (daemon + # spawn/handshake diagnostics), and a head slice of stdout only + # ever showed the allocator preamble. + print("SETUP: index attempt %d did not run (rc=%s):\nstdout:\n%s\nstderr:\n%s" + % (attempt, idx.returncode, idx_out, idx_err)) time.sleep(2) if '"nodes"' not in idx_out: - print("SETUP FAIL: index did not run:\n%s" % idx_out[:300]) + print("SETUP FAIL: index did not run:\nstdout:\n%s\nstderr:\n%s" + % (idx_out, idx_err)) return 2 # Control: prove the symbol is indexed and queryable.