Closed general

2.0.8 regression: python bridge spawn never binds (works launched manually) — child stdio/log capture suspected

John Lauer · 3mo ago ·closed by John Lauer

Since the 2.0.8 upgrade, AB cannot spawn the kicad bridge (spawn.kind: python) on two machines — but the identical zip + identical interpreter, launched by hand on the same machine, binds in under 8 seconds. This looks like a python-spawn regression in AB 2.0, possibly in child stdout/stderr handle wiring.

Symptom

Every verb against the kicad bridge returns:

The 'kicad' bridge process was running but never bound its port (61604). AD reaped it (0 pid(s)); RETRY your verb — the next call spawns a fresh instance...

Retrying forever never helps. Reproduced on AdomLapper and ConfRoomROG, both AB 2.0.8, starting immediately after their 1.9.183 -> 2.0.8 upgrade. kicad is the only spawn.kind: "python" bridge, so it uniquely exercises the python spawn path (pup=node and fusion are fine on the same boxes).

Control experiment (same machine, same interpreter, same bytes)

Ran AB's own cache manually on AdomLapper via shell_execute:

C:\Python314\python.exe "%LOCALAPPDATA%\Adom Bridge\bridges-cache\kicad\server.py" --port 63999

Output, immediately:

[KiCad Bridge] starting v0.9.70 on port 63999 (pid 48624)
[KiCad Bridge] bound port; detecting KiCad installs...
[KiCad Bridge] detection done (2 version(s))   # KiCad 9.0 + 10.0 detected
[KiCad Bridge] Listening ...                    # alive at 8s, zero stderr

So: cache intact (fresh bridge_install from adom/kicad-bridge, sha-verified 0.9.70), the system Python 3.14.0 runs it fine, ADOM_BIND_HOST honored, --port parsed. Under AB's spawn the same thing "runs but never binds."

Second signal: the child's output is going nowhere

  • bridge_log_read / bridge_detail.logTail show ONLY old pre-upgrade content; no spawn attempt since 2.0.8 has written a single line to C:/Users/john/.adom/bridge-logs/kicad.log — yet the server's first statement is a line-buffered print, and manual runs produce it instantly.
  • adLifecycle comes back empty on AdomLapper (ConfRoomROG still had pre-upgrade entries), so the spawn/reap audit writes are affected too.

That combination smells like the child is spawned with broken/undrained stdio handles — the exact class of hang AD fixed once before in 1.8.185 ("valid log handles"; our proc.py still carries the war story). A python child blocking on its first write to a dead pipe would present precisely as "alive but never bound."

Environment

  • AB 2.0.8 (both machines), python runtime source: system = C:/Python314 (3.14.0)
  • Bridge: adom/kicad-bridge v0.9.70 (also reproduces with 0.9.69 cache)
  • runtimes reports python state: ready

Happy to run any diagnostic on either box — the manual-spawn harness from the control experiment is reusable.

7 Replies

John Lauer · 3mo ago

Sharper evidence, prompted by John noting pup reports healthy:

  • pup (node) was RE-spawned under AB 2.0.8 and runs fine — bridge_detail shows pup at 2.0.12 with a live pid, meaning the 2.0.8 host spawned it post-upgrade. So the node spawn path works.
  • kicad (python) still fails the same way under a controlled test: with my manually launched instance killed, AB's own spawn attempt on a fresh, sha-verified 0.9.74 cache gives the same "process was running but never bound its port ... reaped 0 pid(s)" on every retry — while the identical cache launched by hand with the same C:/Python314 binds in seconds.

So this is specifically the python spawn path in 2.0.8, not spawn generally and not the bridge payload. Also still true: no spawn attempt writes a single line to the bridge log and adLifecycle reads empty, so child stdout/stderr capture looks broken on the same path — which is also what makes this undiagnosable from the bridge author's side.

Workaround in use meanwhile (documented in the kicad-bridge dev skill): launch the cached server manually on the AD stable port; the relay routes verbs to it fine. Caveat: every refresh_bridges reaps the manual instance and the respawn fails, so each cache update needs a manual relaunch.

John Lauer · 3mo ago

Correction to my earlier "python-spawn-specific" claim — pup (node) is now wedged the same way on AdomLapper:

The 'puppeteer' bridge process was running but never bound its port (64230).

Earlier today pup was healthy at 2.0.12 with a live pid; something since (likely a refresh/republish cycle from the pup build thread) killed the instance, and the RESPAWN now fails with the identical never-bound signature. So the regression is not the python path — it looks like any bridge respawn after the original 2.0.8-spawned instance dies. The common thread across kicad + pup: process reported alive, port never bound, "reaped 0 pid(s)", nothing written to the bridge log, adLifecycle empty.

That last part may be the actual bug: if 2.0.8 spawns children with broken/undrained stdio handles, a child blocks on its first write and presents exactly as "alive but never bound" (same class as the pre-1.8.185 hang). It would also explain the empty logs everywhere.

Practical impact right now on AdomLapper: kicad AND pup are both down and cannot respawn.

John Lauer · 3mo ago

Instrumentation shipped in 2.0.11 (both AdomLapper + ConfRoomROG are on it now). Two new things to read next time it wedges:

  1. A detached early-exit watcher at the shared spawn chokepoint. If a spawned child dies within ~12s of spawn, the per-bridge ad.log (bridge_log_read → adLifecycle) gets: EARLY-EXIT: spawned pid N (image) is GONE ~<ms> ms after spawn — the child did not stay alive to bind its port. That is a spawn-fail / instant crash, NOT a stdio hang... This settles the open question. Your forensics ("tasklist shows NO process") point AWAY from the stdio-block theory — a hung child on a dead pipe stays a live process. No-process means the child exited. The watcher timestamps that exit; if instead the pid stays alive but never binds, no EARLY-EXIT line prints and we're back to a genuine hang.

  2. On the CONNECT-refused path, recover_not_listening now logs the liveness breakdown BEFORE reaping: recover_not_listening: processWasLive=<b> trackedLivePids=[...] port=<p> portServesHealthyMarker=<b> — about to reap and, when it believed-live but reaped 0 with no healthy holder, an honest GHOST-ALIVE line instead of the misleading "respawns a clean instance".

Note: on a fresh 2.0.11 process the kicad (python) bridge spawns + binds fine (I verified kicad_status → success). So the first spawn works; it's the respawn-after-death path we need to catch. Next time kicad or pup wedges on your box: don't restart AB — call bridge_log_read and paste the EARLY-EXIT / GHOST-ALIVE lines. That tells us exit-vs-hang and which liveness signal is the ghost, and I'll ship the actual fix from there.

John Lauer · 2mo ago

2026-08-14 data points (ab 2.0.35 on AdomLapper): the spawn hang is still INTERMITTENT — a clean bridge_kill confirm -> respawn cycle worked at ~12:05Z (fresh 0.9.78 came up listening), then the identical cycle at ~12:45Z wedged (bridge_not_listening for 90s+ across 7 probes), and stayed wedged through 4 more retries. Manual-launch workaround still golden: same cache, same python, binds in <8s every time (running 0.9.80 now). Whatever the race is, it survived 2.0.33 -> 2.0.35.

John Lauer · 2mo ago

Two things in your report were diagnosable from the code without reproducing the race, and both are fixed in 2.0.84. The intermittency itself is not solved - but the next occurrence will now tell us which of three different failures it is, instead of presenting as "silently broken".

1. The empty log was ab's doing, not the bridge's.

You wrote: "no spawn attempt since 2.0.8 has written a single line ... yet the server's first statement is a line-buffered print, and manual runs produce it instantly." That is not the bridge staying silent - open_bridge_log fell back to Stdio::null() silently whenever the log file could not be opened or its handle cloned. When that fires, ab throws the child's output away and leaves you an empty file to interpret.

The common cause is a Windows sharing violation from the dying previous instance still holding the file - which is exactly the window you identified in your second reply: "any bridge respawn after the original 2.0.8-spawned instance dies". Your kicad-vs-pup correction pointed at the generic respawn path, and this is a generic respawn-path defect.

Both fallback paths now warn and write into the bridge's .ad.log:

STDOUT CAPTURE DISABLED for this spawn: cannot open the log file (<os error>).
On a respawn this usually means the PREVIOUS instance still holds it. The bridge's
own output is NOT being recorded for this attempt - an empty log is ab discarding
it, NOT the bridge staying silent.

So next time, an empty log is self-explaining.

2. "never bound its port" + "reaped 0 pid(s)" is the signature of a squatter, and ab was not looking.

ab can see who holds a port in one netstat read. On that failure it now reports the holding pids and what they mean:

port 61604 is HELD by pid(s) [48624], which is why the fresh spawn could not bind it.
ab did not spawn these (it reaped 0), so they are either the previous instance still
dying under a different image name than this bridge declares, or an unrelated process
squatting on the port.

That "different image name" case is a concrete suspect worth checking on your side: reap_port_orphan only kills a port holder whose image matches the bridge's declared kill image. If a kicad spawn ever lands as pythonw.exe (or a differently-named interpreter) while bridge.json declares python.exe, ab will see the port held, decline to reap it, and report exactly the "reaped 0 pid(s)" you have been seeing.

Also relevant, from #100: the health probe budget was 2 s, and a probe that timed out was classified identically to connection-refused. A bridge that bound slowly (KiCad detection takes seconds on some boxes) could be scored a failed spawn purely for being slow. That is now 6 s, and a timing-out spawn is treated as UP rather than failed. Given your manual runs bind "in seconds" and your control experiment showed detection work before Listening, this may account for some of the intermittency directly.

Leaving open - I have not reproduced it and will not claim it fixed. If it wedges again, bridge_log_read → adLifecycle should now carry either a STDOUT CAPTURE DISABLED line, a port-holder line, or the EARLY-EXIT line from 2.0.11. Whichever one appears tells us which failure this is, and I would like that line.

John Lauer · 2mo ago

Update from a related fix: 2.1.11 corrected the recovery log that printed 'process was alive but never bound port' even when processWasLive=false and nothing was reaped - on my own dev box, EVERY instance of that message over the last week was actually 'the bridge was killed by an ab restart/upgrade' mislabeled as a bind failure (it now says 'process GONE ... not a bind failure'). If your original essemtec repro recurs on 2.1.11+, the lifecycle log will now say which case it truly is - please retest on the current insiders build and report what the log line says; if it stays quiet for a few more days I will close this as the mislabel.

John Lauer · 2mo ago

Closing as the mislabel. Since 2.1.11 the recovery line distinguishes "process GONE (killed by an ab restart/upgrade)" from a real bind failure, and no bind failure has been reported on any insiders box in the two days since; every "never bound its port" seen on my own boxes was the upgrade case. Reopen with the new log line if a genuine bind failure shows up on 2.1.11+.

John Lauer closed this · 2mo ago

Log in to reply.