From 094a72dec5e455a7dc2992c15b6fd0f91b4eae9a Mon Sep 17 00:00:00 2001 From: Eric Gustafson Date: Sun, 26 Jul 2026 16:47:41 +0000 Subject: [PATCH 1/2] Make server startup and teardown failures diagnosable Three failures accounted for 54 of the 62 DecLib errors we logged across a CTF where DecLib was the sole decompiler interface. None of them told the user what had actually happened, and each one ended with an agent abandoning the CLI for a hand-rolled script. **"Failed to open database " (14x).** Reproduced: it is what you get when a second server opens a project another server already holds. `--force` is documented as "run a second copy", but the default project dir is derived from binary+backend alone, so the second server always collided with the first and died. Forced copies now get their own project dir, and `--force` works: before: Failed to open database /tmp/orig after: two live servers, project_dir orig-5a3e46a4 and orig-5a3e46a4-722556f738 The bare message also reads like file corruption, so any log carrying it now gets an explanation naming the real cause and the three ways out (`--id`, `--replace`, `--project-dir`). **"Timed out waiting Ns for server to start" (19x).** Two problems. The advice said "Check backend dependencies (e.g. GHIDRA_INSTALL_DIR)" whatever the backend was -- actively misleading on IDA. It is now backend-aware. And the wait was silent, so a legitimately slow load was indistinguishable from a hang; agents retried at 180s, 240s, then 300s, burning ~12 minutes before giving up. The wait now reports every 10s, surfacing the backend's own last log line: [10s] INFO | declib.api.decompiler_server | Using headless interface utilizing ida [20s] still starting (5s left)... Timed out waiting 25s ... Check the IDA install and that its licence/EULA is accepted (`decompiler backend status ida`). **"No running decompiler server matches {...}" (21x).** The registry prunes dead records during lookup, so a server that died left no trace and the error read as "you never started one". list_servers/find_servers can now report what they reaped, and the error names the corpse: Decompiler server 078c974380 is no longer running (binary: /tmp/orig). It died or was stopped; its analysis is gone. Reload it with: decompiler load /tmp/orig --backend ida Deliberately not doing silent auto-revive: re-analysis can take minutes, and quietly spending them (or quietly losing unsaved annotations) is a worse surprise than an accurate error naming the command to run. Tests: backend-aware hints for every backend, the lock explanation fires only on lock failures, and the registry reports pruned records. Co-Authored-By: Claude Opus 5 (1M context) --- declib/api/server_registry.py | 21 +++++-- declib/cli/decompiler_cli.py | 105 ++++++++++++++++++++++++++++++++-- tests/test_decompiler_cli.py | 72 +++++++++++++++++++++++ 3 files changed, 190 insertions(+), 8 deletions(-) diff --git a/declib/api/server_registry.py b/declib/api/server_registry.py index 6b1c8164..5ff6ac81 100644 --- a/declib/api/server_registry.py +++ b/declib/api/server_registry.py @@ -86,8 +86,14 @@ def _is_record_live(record: Dict) -> bool: return True -def list_servers(prune_stale: bool = True) -> List[Dict]: - """Return all server records, optionally dropping and removing stale entries.""" +def list_servers(prune_stale: bool = True, pruned: Optional[List[Dict]] = None) -> List[Dict]: + """Return all server records, optionally dropping and removing stale entries. + + Pass a list as ``pruned`` to receive the records that were removed. Without + it, a server that has died is simply gone, and a caller can only report + "no server matches" — which reads as "you never started one" rather than + "yours died, here is how to bring it back". + """ records: List[Dict] = [] try: entries = sorted(_registry_dir().glob("*.json")) @@ -103,6 +109,8 @@ def list_servers(prune_stale: bool = True) -> List[Dict]: continue if prune_stale and not _is_record_live(record): + if pruned is not None: + pruned.append(record) try: entry.unlink() except FileNotFoundError: @@ -148,11 +156,16 @@ def find_servers( binary_path: Optional[str] = None, binary_hash: Optional[str] = None, backend: Optional[str] = None, + pruned: Optional[List[Dict]] = None, ) -> List[Dict]: - """Return all server records matching the provided filters.""" + """Return all server records matching the provided filters. + + ``pruned`` is forwarded to :func:`list_servers`; pass a list to learn which + dead servers were reaped during this lookup. + """ matches: List[Dict] = [] binary_path_resolved = str(Path(binary_path).expanduser().resolve()) if binary_path else None - for record in list_servers(): + for record in list_servers(pruned=pruned): if binary_path_resolved: record_path = record.get("binary_path") if not record_path: diff --git a/declib/cli/decompiler_cli.py b/declib/cli/decompiler_cli.py index fb4c05b3..18f378cb 100644 --- a/declib/cli/decompiler_cli.py +++ b/declib/cli/decompiler_cli.py @@ -191,9 +191,11 @@ def _select_server( backend: Optional[str], ) -> Dict: """Pick a server record from the registry, or error out with a helpful message.""" + reaped: List[Dict] = [] records = server_registry.find_servers( binary_path=binary_path, backend=backend, + pruned=reaped, ) if server_id: records = [r for r in records if r.get("id") == server_id] @@ -201,6 +203,28 @@ def _select_server( if not records: filters = {"id": server_id, "binary_path": binary_path, "backend": backend} active = {k: v for k, v in filters.items() if v} + + # A server that died is reaped from the registry by the lookup above, + # so "no server matches" otherwise reads as "you never started one". + # If one of the corpses matches what was asked for, say so and hand + # back the exact command to bring it back. + dead = [ + r for r in reaped + if (not server_id or r.get("id") == server_id) + and (not backend or r.get("backend") == backend) + ] + if dead: + corpse = dead[0] + binary = corpse.get("binary_path") or "" + reload_cmd = f"decompiler load {binary}" + if corpse.get("backend"): + reload_cmd += f" --backend {corpse['backend']}" + raise SystemExit( + f"Decompiler server {corpse.get('id')} is no longer running " + f"(binary: {binary}). It died or was stopped; its analysis is " + f"gone.\nReload it with:\n {reload_cmd}" + ) + raise SystemExit( "No running decompiler server matches " f"{active or '(no filters)'}. Start one with `decompiler load `." @@ -324,22 +348,69 @@ def _read_server_log_tail( def _server_start_error(message: str, log_path: Optional[Path]) -> SystemExit: lines = [message] + tail = _read_server_log_tail(log_path) if log_path is not None else "" + + # "Failed to open database " is what a backend says when another + # process already holds that project's database. On its own it reads like + # a corrupt or missing file, which sends people down the wrong path. + if "Failed to open database" in tail: + lines.append( + "\nThat usually means another decompiler server already holds this " + "project's database.\nCheck with `decompiler list`, then either " + "target it (`--id `), replace it (`--replace`), or give this " + "one its own project (`--project-dir `)." + ) + if log_path is not None: lines.append(f"Server log: {log_path}") - tail = _read_server_log_tail(log_path) if tail: lines.extend(("Server log tail:", tail)) return SystemExit("\n".join(lines)) +def _backend_start_hint(backend: Optional[str]) -> str: + """Advice that matches the backend actually in use. + + The old text named GHIDRA_INSTALL_DIR unconditionally, which is actively + misleading when the backend is IDA — it sends people to check an + environment variable that has nothing to do with their failure. + """ + hints = { + "ghidra": "Check GHIDRA_INSTALL_DIR points at a Ghidra install.", + "ida": "Check the IDA install and that its licence/EULA is accepted " + "(`decompiler backend status ida`).", + "binja": "Check the Binary Ninja install and licence " + "(`decompiler backend status binja`).", + "angr": "Check angr is importable (`decompiler backend status angr`).", + "jadx": "Check the JADX runtime (`decompiler backend status jadx`).", + } + generic = ("Run `decompiler backend status ` to check the runtime, " + "and read the server log below.") + return hints.get(backend or "", generic) + + +# How long to sit silent before telling the user what the server is doing. +_SERVER_PROGRESS_INTERVAL = 10.0 + + def _wait_for_server( server_id: str, process: Optional[subprocess.Popen] = None, log_path: Optional[Path] = None, timeout: float = _SERVER_START_TIMEOUT, + backend: Optional[str] = None, ) -> Dict: - """Block until a server with `server_id` appears in the registry or timeout.""" - deadline = time.time() + timeout + """Block until a server with `server_id` appears in the registry or timeout. + + Reports progress while waiting. Analyzing a large binary legitimately takes + minutes, but a silent wait is indistinguishable from a hang — which is how + a slow load gets abandoned for a hand-rolled script. + """ + start = time.time() + deadline = start + timeout + next_report = start + _SERVER_PROGRESS_INTERVAL + last_line = "" + while time.time() < deadline: record = server_registry.find_server(server_id=server_id) if record and record.get("socket_path") and os.path.exists(record["socket_path"]): @@ -352,10 +423,27 @@ def _wait_for_server( f"{exit_status} before registering.", log_path, ) + + now = time.time() + if now >= next_report: + # Surface the backend's own last log line, so "still analyzing" is + # visibly different from "wedged". + tail = _read_server_log_tail(log_path, max_bytes=2048) + current = tail.splitlines()[-1].strip() if tail else "" + elapsed = now - start + if current and current != last_line: + print(f" [{elapsed:.0f}s] {current}", file=sys.stderr) + last_line = current + else: + print(f" [{elapsed:.0f}s] still starting " + f"({timeout - elapsed:.0f}s left)...", file=sys.stderr) + next_report = now + _SERVER_PROGRESS_INTERVAL + time.sleep(_SERVER_POLL_INTERVAL) + raise _server_start_error( f"Timed out waiting {timeout:g}s for server {server_id} to start. " - "Check backend dependencies (e.g. GHIDRA_INSTALL_DIR) and retry.", + f"{_backend_start_hint(backend)}", log_path, ) @@ -406,6 +494,14 @@ def cmd_load(args) -> int: project_dir = Path(args.project_dir).expanduser().resolve() else: project_dir = _default_project_dir(binary_path, backend) + # --force means "run a second copy", but the default project dir is + # derived from binary+backend alone, so the second server would open + # the same on-disk database as the first. IDA (and Ghidra) hold a lock + # on it, and the new server dies with a bare + # "Failed to open database " that names neither the lock nor + # the server holding it. Give each forced copy its own project dir. + if args.force and existing: + project_dir = project_dir.with_name(f"{project_dir.name}-{server_id}") log_path = _server_log_path(server_id) process = _spawn_server( binary_path, @@ -419,6 +515,7 @@ def cmd_load(args) -> int: process=process, log_path=log_path, timeout=args.timeout, + backend=backend, ) _emit(args, { "status": "started", diff --git a/tests/test_decompiler_cli.py b/tests/test_decompiler_cli.py index bd163aab..dbda3a29 100644 --- a/tests/test_decompiler_cli.py +++ b/tests/test_decompiler_cli.py @@ -2104,3 +2104,75 @@ def test_safe_filename_is_filesystem_safe_and_unique(self): self.assertEqual(_safe_filename("", 0x55), "00000055.c") # Two same-named functions at different addresses cannot collide. self.assertNotEqual(_safe_filename("f", 1), _safe_filename("f", 2)) +class TestServerStartupDiagnostics(unittest.TestCase): + """Startup/teardown diagnostics. No backend required.""" + + def test_backend_hint_matches_the_backend(self): + """The old text named GHIDRA_INSTALL_DIR whatever the backend was.""" + from declib.cli.decompiler_cli import _backend_start_hint + + self.assertIn("GHIDRA_INSTALL_DIR", _backend_start_hint("ghidra")) + for other in ("ida", "binja", "angr", "jadx"): + with self.subTest(backend=other): + hint = _backend_start_hint(other) + self.assertNotIn("GHIDRA_INSTALL_DIR", hint) + self.assertIn(other, hint) + # Unknown/absent backend still gets something actionable. + self.assertIn("backend status", _backend_start_hint(None)) + + def test_database_lock_gets_an_explanation(self): + """A bare "Failed to open database" reads like corruption.""" + import tempfile as _tf + from declib.cli.decompiler_cli import _server_start_error + + with _tf.NamedTemporaryFile("w", suffix=".log", delete=False) as fh: + fh.write("ERROR - Failed to start server: Failed to open database /tmp/x\n") + log = Path(fh.name) + try: + text = str(_server_start_error("server died", log)) + self.assertIn("already holds this project's database", text) + self.assertIn("--replace", text) + self.assertIn("--project-dir", text) + finally: + log.unlink() + + def test_unrelated_failure_gets_no_lock_advice(self): + import tempfile as _tf + from declib.cli.decompiler_cli import _server_start_error + + with _tf.NamedTemporaryFile("w", suffix=".log", delete=False) as fh: + fh.write("ERROR - Failed to start server: no such file\n") + log = Path(fh.name) + try: + self.assertNotIn("already holds", str(_server_start_error("died", log))) + finally: + log.unlink() + + +class TestRegistryPruneReporting(unittest.TestCase): + """list_servers must be able to say what it reaped.""" + + def test_pruned_records_are_reported(self): + import tempfile as _tf + from declib.api import server_registry as reg + + with _tf.TemporaryDirectory() as tmp: + os.environ["DECLIB_SERVER_REGISTRY"] = tmp + try: + dead = { + "id": "deadbeef01", + "pid": 999999, # not a live process + "binary_path": "/tmp/gone", + "backend": "ida", + "socket_path": os.path.join(tmp, "nope.sock"), + } + Path(tmp, "deadbeef01.json").write_text(json.dumps(dead)) + + reaped = [] + live = reg.list_servers(pruned=reaped) + self.assertEqual(live, []) + self.assertEqual([r["id"] for r in reaped], ["deadbeef01"]) + # The caller can now name the binary in its error message. + self.assertEqual(reaped[0]["binary_path"], "/tmp/gone") + finally: + os.environ.pop("DECLIB_SERVER_REGISTRY", None) From 8b7e5f4bba32a9cbd58e11437fabee158c659d27 Mon Sep 17 00:00:00 2001 From: Eric Gustafson Date: Wed, 29 Jul 2026 02:59:05 +0000 Subject: [PATCH 2/2] Keep a dead server explainable after its record is pruned one". It only works for the *first* command after the death, though: that command prunes the registry entry, and every command after it goes blind again. The command that usually gets there first is `list` -- the single most-used verb -- and it prints a bare "No running decompiler servers", which reads exactly like nothing was ever started. So in practice the diagnosis is destroyed by the command used to check state. Measured on a 40-binary run: of 79 "missing server" errors, only **10** carried the useful message. The other **69** had already had the corpse eaten by an intervening `list`. Reproduced deterministically: load -> kill -9 -> list_functions --id X "server X is no longer running ... reload with: decompiler load ..." load -> kill -9 -> list -> list_functions --id X "No running decompiler server matches {'id': 'X'}." Pruning now leaves a tombstone next to the registry entry, so the death stays explainable for any later command. `list` reports recent deaths with the reload command instead of implying nothing ever ran, and a successful `load` of the same binary clears the tombstone so a stale death is never reported as current. Tombstones are a hint, not a log: capped at the 16 most recent, and excluded from the live-record glob so one can never be mistaken for a running server. Co-Authored-By: Claude Opus 5 (1M context) --- declib/api/server_registry.py | 83 ++++++++++++++++++++++++++++++++++- declib/cli/decompiler_cli.py | 29 ++++++++++++ tests/test_decompiler_cli.py | 78 ++++++++++++++++++++++++++++++++ 3 files changed, 189 insertions(+), 1 deletion(-) diff --git a/declib/api/server_registry.py b/declib/api/server_registry.py index 5ff6ac81..100c4f6b 100644 --- a/declib/api/server_registry.py +++ b/declib/api/server_registry.py @@ -72,6 +72,83 @@ def unregister_server(server_id: str) -> bool: return False +# A pruned record is the only evidence that a server ever existed. Deleting it +# outright means the *next* command can explain what happened but every command +# after that cannot -- and the command agents run most is `list`, which prunes. +# Measured on a 40-binary benchmark: only 10 of 79 "missing server" errors +# carried the useful diagnosis; 69 had already had the corpse eaten by an +# intervening `list`. So pruning leaves a tombstone behind instead. +_TOMBSTONE_SUFFIX = ".dead.json" +_TOMBSTONE_KEEP = 16 + + +def _tombstone_path(server_id: str) -> Path: + return _registry_dir() / f"{server_id}{_TOMBSTONE_SUFFIX}" + + +def _write_tombstone(record: Dict) -> None: + """Record that a server died, so later commands can still say so.""" + server_id = record.get("id") + if not server_id: + return + payload = dict(record) + payload["died_at"] = time.time() + try: + path = _tombstone_path(str(server_id)) + tmp_path = path.with_suffix(".tmp") + with open(tmp_path, "w") as f: + json.dump(payload, f, indent=2, default=str) + os.replace(tmp_path, path) + except Exception as exc: + _l.debug("Failed to write tombstone for %s: %s", server_id, exc) + return + _trim_tombstones() + + +def _trim_tombstones() -> None: + """Keep only the most recent tombstones; they are a hint, not a log.""" + try: + stones = sorted( + _registry_dir().glob(f"*{_TOMBSTONE_SUFFIX}"), + key=lambda p: p.stat().st_mtime, + reverse=True, + ) + except Exception: + return + for old in stones[_TOMBSTONE_KEEP:]: + try: + old.unlink() + except Exception: + pass + + +def list_tombstones() -> List[Dict]: + """Recently-died servers, newest first.""" + out: List[Dict] = [] + try: + stones = sorted(_registry_dir().glob(f"*{_TOMBSTONE_SUFFIX}")) + except FileNotFoundError: + return [] + for entry in stones: + try: + with open(entry, "r") as f: + out.append(json.load(f)) + except Exception: + continue + out.sort(key=lambda r: r.get("died_at") or 0, reverse=True) + return out + + +def clear_tombstone(server_id: str) -> None: + """Forget a death -- called when a binary is successfully reloaded.""" + try: + _tombstone_path(str(server_id)).unlink() + except FileNotFoundError: + pass + except Exception: + pass + + def _is_record_live(record: Dict) -> bool: pid = record.get("pid") socket_path = record.get("socket_path") @@ -96,7 +173,10 @@ def list_servers(prune_stale: bool = True, pruned: Optional[List[Dict]] = None) """ records: List[Dict] = [] try: - entries = sorted(_registry_dir().glob("*.json")) + entries = sorted( + e for e in _registry_dir().glob("*.json") + if not e.name.endswith(_TOMBSTONE_SUFFIX) + ) except FileNotFoundError: return [] @@ -111,6 +191,7 @@ def list_servers(prune_stale: bool = True, pruned: Optional[List[Dict]] = None) if prune_stale and not _is_record_live(record): if pruned is not None: pruned.append(record) + _write_tombstone(record) try: entry.unlink() except FileNotFoundError: diff --git a/declib/cli/decompiler_cli.py b/declib/cli/decompiler_cli.py index 18f378cb..74ab192d 100644 --- a/declib/cli/decompiler_cli.py +++ b/declib/cli/decompiler_cli.py @@ -213,6 +213,16 @@ def _select_server( if (not server_id or r.get("id") == server_id) and (not backend or r.get("backend") == backend) ] + # `reaped` only holds servers *this* call pruned. Whichever command ran + # first after the death already pruned it -- usually `list` -- so for + # every later command the corpse is only in the tombstones. + if not dead: + dead = [ + r for r in server_registry.list_tombstones() + if (not server_id or r.get("id") == server_id) + and (not backend or r.get("backend") == backend) + and (not binary_path or r.get("binary_path") == binary_path) + ] if dead: corpse = dead[0] binary = corpse.get("binary_path") or "" @@ -517,6 +527,10 @@ def cmd_load(args) -> int: timeout=args.timeout, backend=backend, ) + # The binary is usable again; stop reporting the old death. + for stone in server_registry.list_tombstones(): + if stone.get("binary_path") == str(binary_path): + server_registry.clear_tombstone(str(stone.get("id"))) _emit(args, { "status": "started", "id": record["id"], @@ -559,6 +573,7 @@ def cmd_list(args) -> int: return 0 if not records: print(f"No running decompiler servers. (registry: {registry_dir})") + _report_recent_deaths() return 0 print(f"{'ID':<12} {'BACKEND':<8} {'PID':<8} BINARY") for r in records: @@ -567,6 +582,20 @@ def cmd_list(args) -> int: return 0 + +def _report_recent_deaths() -> None: + """Tell the caller a server died, rather than letting it read as never-started.""" + stones = server_registry.list_tombstones() + if not stones: + return + print("\nRecently died (analysis is gone; reload to continue):") + for stone in stones[:5]: + binary = stone.get("binary_path") or "" + cmd = f"decompiler load {binary}" + if stone.get("backend"): + cmd += f" --backend {stone['backend']}" + print(f" {stone.get('id','?'):<12} {binary}\n reload: {cmd}") + def _stop_server_by_record(record: Dict, save_mode: Optional[str] = None) -> bool: """Shut down the server process backing `record`. diff --git a/tests/test_decompiler_cli.py b/tests/test_decompiler_cli.py index dbda3a29..8f59d2ba 100644 --- a/tests/test_decompiler_cli.py +++ b/tests/test_decompiler_cli.py @@ -2176,3 +2176,81 @@ def test_pruned_records_are_reported(self): self.assertEqual(reaped[0]["binary_path"], "/tmp/gone") finally: os.environ.pop("DECLIB_SERVER_REGISTRY", None) + +class TestServerTombstones(unittest.TestCase): + """A death must stay explainable after the corpse is pruned. + + `list` prunes, and `list` is the command agents run most, so without a + tombstone the useful "your server died" diagnosis is destroyed by the very + command used to check state -- and every later command reads as though no + server was ever started. + """ + + def setUp(self): + import tempfile + self._tmp = tempfile.TemporaryDirectory() + os.environ["DECLIB_SERVER_REGISTRY"] = self._tmp.name + + def tearDown(self): + os.environ.pop("DECLIB_SERVER_REGISTRY", None) + self._tmp.cleanup() + + def _dead_record(self): + from declib.api import server_registry + server_registry.register_server({ + "id": "deadbeef01", "socket_path": "/nonexistent/x.sock", + "binary_path": "/tmp/gone", "backend": "ida", "pid": 999999, + }) + + def test_pruning_leaves_a_tombstone(self): + from declib.api import server_registry + + self._dead_record() + self.assertEqual(server_registry.list_servers(), []) + stones = server_registry.list_tombstones() + self.assertEqual([s["id"] for s in stones], ["deadbeef01"]) + self.assertEqual(stones[0]["binary_path"], "/tmp/gone") + self.assertIn("died_at", stones[0]) + + def test_diagnosis_survives_a_second_lookup(self): + """The regression: the first call pruned, so the second went blind.""" + from declib.api import server_registry + + self._dead_record() + server_registry.list_servers() # first call eats the corpse + stones = server_registry.list_tombstones() + self.assertTrue(stones, "second lookup must still be able to explain") + + def test_tombstones_are_not_mistaken_for_live_records(self): + from declib.api import server_registry + + self._dead_record() + server_registry.list_servers() + # The tombstone is a *.json file in the same directory; it must never + # come back as a server. + self.assertEqual(server_registry.list_servers(), []) + self.assertIsNone(server_registry.find_server(server_id="deadbeef01")) + + def test_reload_clears_the_tombstone(self): + from declib.api import server_registry + + self._dead_record() + server_registry.list_servers() + self.assertTrue(server_registry.list_tombstones()) + server_registry.clear_tombstone("deadbeef01") + self.assertEqual(server_registry.list_tombstones(), []) + + def test_tombstones_are_capped(self): + """A hint, not a log -- they must not grow without bound.""" + from declib.api import server_registry + + for i in range(server_registry._TOMBSTONE_KEEP + 10): + server_registry.register_server({ + "id": f"corpse{i:04d}", "socket_path": "/nonexistent/x.sock", + "binary_path": f"/tmp/gone{i}", "backend": "ida", "pid": 999999, + }) + server_registry.list_servers() + self.assertLessEqual(len(server_registry.list_tombstones()), + server_registry._TOMBSTONE_KEEP) + +