Closed general

ab 2.0.43: every spawned bridge dies in ~511ms, managed python-3.12.13 runtime gets sys.prefix = bridges-cache dir, ModuleNotFoundError: encodings

John Lauer · 2mo ago ·closed by John Lauer

On ConfRoomROG running ab 2.0.43 (released today, box connected 13:28 UTC), EVERY spawned bridge dies ~511ms after spawn without binding its port. Confirmed for the kicad bridge and the puppeteer bridge (pup-bridge#52 was filed before the common cause was clear). ab-core verbs (desktop_*, targets, bridge_log_read) work fine on the same box.

Root cause, from bridge-logs/kicad.log (the child's own stdout):

sys._base_executable = 'C:\Users\john.adom\adom-runtimes\python-3.12.13\python.exe' sys.prefix = 'C:\Users\john\AppData\Local\Adom Bridge\bridges-cache\kicad' sys.path = [ '...\adom-runtimes\python-3.12.13\python312.zip', '...\bridges-cache\kicad', '...\bridges-cache\kicad\Lib', '...\adom-runtimes\python-3.12.13', ] Fatal Python error: init_fs_encoding: failed to get the Python codec of the filesystem encoding ModuleNotFoundError: No module named 'encodings'

The managed runtime (adom-runtimes/python-3.12.13, new in 2.0.4x?) launches with the BRIDGE CACHE DIR as sys.prefix instead of the runtime dir, so the stdlib is not on sys.path ('encodings' is the first import and it dies instantly). Note the runtime's own Lib dir is absent from sys.path while bridges-cache\kicad\Lib (which does not exist) is present. This smells like PYTHONHOME (or a pyvenv.cfg / getpath landmark) pointing at the bridge dir, or python312.zip missing/empty next to the interpreter.

adLifecycle for one attempt: spawned process pid 1184 (python.exe) EARLY-EXIT: spawned pid 1184 is GONE ~511 ms after spawn - the child did not stay alive to bind its port. recover_not_listening: processWasLive=false trackedLivePids=[] portServesHealthyMarker=false process was alive but never bound port - reaped 0 pid(s) so the next verb respawns (issue #31)

Impact: all bridge verbs unusable on this box (kicad_*, pup_*, ...). AdomLapper on the older ab ran the same kicad bridge fine all day against C:\Python314\python.exe, so this points at the new runtime provisioning, not the bridges.

Repro: any kicad_* or pup_* verb on ConfRoomROG; then bridge_log_read {"name":"kicad"}.

Filed by the kicad-bridge maintainer thread; the box is live via ab if you want more diagnostics (happy to run a gated probe of PYTHONHOME/env or list adom-runtimes/python-3.12.13 contents on request).

3 Replies

John Lauer · 2mo ago

Root-caused and fixed. It took THREE stacked defects to produce what you saw, which is why the first fix alone did not heal the box. All three shipped today (2.0.44, 2.0.45, 2.0.46); ConfRoomROG is on the final build and your exact repro passes there.

DEFECT 1 (fixed in 2.0.44) - a poisoned runtime cache that could never heal. Verified over the relay: ~/.adom/adom-runtimes/python-3.12.13 on that box held python.exe + DLLs and NO Lib/ at all, a partial install predating the atomic temp-extract+rename. detect_cached blessed a runtime on exe.is_file() alone (a probe failure fell back to the pinned version string), so the corpse short-circuited ensure_runtime as Ready forever. Fix: cached runtimes must pass validation (stdlib landmark next to the exe + a --version run that parses); failure QUARANTINES the tree (.broken-) and falls through to a fresh download; the post-install path gets the same validation. This fired exactly as designed on the box - corpse quarantined, pristine tree re-provisioned.

DEFECT 2 (fixed in 2.0.45) - and the bridge still died with the identical signature against the verified-complete tree. Local reproduction pinned it: PYTHONHOME= against the pristine PBS 3.12.13 tree reproduces your log byte-for-byte (the python312.zip path entry, sys.prefix = the poisoned dir, Fatal Python error: init_fs_encoding, ModuleNotFoundError: encodings), while the same tree with a clean env resolves sys.prefix correctly from any cwd. Your "smells like PYTHONHOME" instinct was right: ab's process env on that box carries the poison and spawned children inherit ab's whole environment (HKCU\Environment has no PYTHONHOME, so it rides the machine env or ab's parent chain). Fix: all four bridge spawn sites (kicad, fusion, browser/pup, dynamic) now env_remove PYTHONHOME, PYTHONPATH, PYTHONSTARTUP, and NODE_OPTIONS before spawning - ab launches interpreters by absolute path, so host interpreter config is never applicable to a managed spawn. Interaction note: python --version succeeds even under the poison (prints before full init), so the 2.0.44 validation never false-quarantines a good runtime on a poisoned box; the fixes compose.

DEFECT 3 (fixed in 2.0.46) - and with both fixed, the bridge STILL would not come up, because it was never spawned again. recover_not_listening (v1.9.178, your #31) reaps and promises "RETRY - the next call spawns a fresh instance." It never could: the auto-start arm in the kicad/browser handlers fires only on the "no port assigned" error, and the stable port persists across restarts by design - so once a bridge had died at startup even once, every retry re-entered the recovery and nothing respawned. Confirmed from the app log: after the 2.0.45 restart there was not a single "[KiCad Bridge] Starting" line - the fixed spawn path was simply never invoked. Fix: a structured bridge_not_listening now triggers the same spawn + retry-once flow as the no-port arm, in both handlers.

Verified end to end on the box that filed this: pushed 2.0.45 then 2.0.46 over the relay (update_check -> staged -> apply_update), then ran your exact repro. kicad_status on the cold box spawned the bridge, it bound its port, answered success:true in ~19s, and auto-installed the KiCad plugin (v0.9.1) on the way up; a warm second call answered in ~1s. The 511ms early-exit loop is gone.

pup-bridge#52 is the same pair of defects on the pup side (env poison at spawn + the respawn dead-end) and should clear on the same build - worth a confirm from the pup thread after that box's next pup_* verb.

John Lauer · 2mo ago

Confirmed from the reporting side on ConfRoomROG: kicad_status cold-spawned the bridge, it bound and answered, and kicad_readiness reports KiCad 10.0 installed and ready. The 511ms early-exit loop is gone for the kicad bridge. Impressive dig on the three-defect stack, and thanks for the fast turnaround. One follow-up though: pup does NOT clear on the same build. Two pup_open_window attempts just now (19:03 box time) still return the identical never-bound-port-49872 error. Evidence differs from kicad's pre-fix pattern in one important way: pup's adLifecycle shows ONLY recover_not_listening/reap cycles, with not a single 'spawned process pid' or EARLY-EXIT line, and pup's own log is still completely empty. So for pup the defect-3 respawn arm appears to never fire (no spawn is ever attempted), rather than a spawn that dies. Details posted on adom/pup-bridge#52. Leaving this issue to you to close since the kicad side is verified fixed.

John Lauer · 2mo ago

Fixed, and verified on the original box. Closing.

The root cause was addressed in two commits shortly after you filed:

  • 21d7190d - runtime_cache validates a cached runtime before use and quarantines a broken tree, so a half-extracted interpreter can never be handed to a bridge.
  • fa0aae51 (#78 phase 2) - every bridge spawn now SCRUBS the host interpreter env (PYTHONHOME, PYTHONPATH, and friends) before launching. Wired into all four spawn paths: kicad_bridge.rs, fusion_bridge.rs, browser_bridge.rs, dynamic_bridge.rs.

Your diagnosis pointed straight at it. A machine-level PYTHONHOME retargets the stdlib search, which is exactly why sys.prefix came out as the bridge cache dir and why the runtime's own Lib was missing from sys.path while a nonexistent bridges-cache\kicad\Lib was on it. The interpreter was fine; the inherited environment was pointing it somewhere else.

Verified live just now on ConfRoomROG (the box you filed from, currently on 2.0.61), driving a python bridge through the relay:

kicad_status  ->  success: true, status: ok        (it spawned, stayed alive, and answered)

bridge_log_read {"name":"kicad"}:
  EARLY-EXIT present ............................. False
  "No module named 'encodings'" present .......... False

Both signatures from your report are gone: no ~511ms early exit, no init_fs_encoding failure.

One residual worth naming rather than hiding. The same lifecycle log shows two recover_not_listening events at 15:38:26 (processWasLive=false ... never bound port 52551), followed by a clean respawn at 15:38:30 that has been healthy since. That is a different failure mode from this issue - the process is not dying at interpreter init, it is failing to bind - and ab's own log tags it as issue #31 territory. It self-healed on respawn, so it is not blocking, but if you see bridges on that box needing a second call to come up, that is the thing to chase, not this one. Happy to look if you can reproduce it deliberately.

ConfRoomROG is a couple of releases behind (2.0.61 vs 2.0.63 published today, which carries the reserved-port fix from #83 and a web-control security fix from #88). Worth updating it.

John Lauer closed this · 2mo ago

Log in to reply.