Closed bug report

Spawner starts the legacy bridges\kicad folder (0.9.65) while bridge_list reports the bridges-cache build; port held, cache exe exits silently

John Lauer · 2mo ago ·closed by John Lauer

Observed on arav-rog today (ab 2.1.9x, Windows), while swapping the kicad bridge cache to a native build:

  1. bridge_list reported kicad version 1.0.0-alpha.2, spawnKind exe, status running, port 51624 (the contents of %LOCALAPPDATA%\Adom Bridge\bridges-cache\kicad\bridge.json).
  2. The process ab (pid 22468) had actually spawned was C:\Users\arav\AppData\Local\Programs\Python\Python312\python.exe "\\?\C:\Users\arav\AppData\Local\Adom Bridge\bridges\kicad\server.py" --port 51624: the pre-bridges-cache legacy folder, holding BRIDGE_VERSION 0.9.65. Every kicad_* verb was answered by that 0.9.65 bridge (45 verbs in describe) while bridge_list claimed the cache build.
  3. The exe in the cache could not bind the persisted port because the legacy process held it, so it exited; ab still showed running.

So when both bridges\<name> (legacy) and bridges-cache\<name> exist, resume/spawn picks the legacy folder while the registry reads the cache. That silently runs a months-old bridge. Same family as #161 (stray bridges-cache subfolders adopted).

Asks:

  • Never spawn from bridges\<name> when bridges-cache\<name> exists; ideally list the legacy folder as ignored the way #161 does for cache subfolders, and say so in bridge_list.
  • When the spawned child exits within a few seconds (bind failure), report status: failed with the child's stderr instead of running, and do not route verbs to whatever is listening on the persisted port.
  • Optional: bridge_list could include pid and exePath of the process it believes is serving each bridge, so this is visible without process_list.

Remediation applied on arav-rog: killed the stray pid, moved bridges\kicad to bridge-backups\legacy-bridges-kicad-0.9.65-<ts>, resumed; the cache build now answers. Other boxes may carry the same legacy folder.

2 Replies

John Lauer · 2mo ago

Acknowledged; queued right after 2.1.102 (#187 + #188) as its own release, since the spawner is a separate area to prove. Plan from a first read: the registry knows two roots (bundled /bridges/ and the writable bridges-cache/) but the KiCad spawn path still reaches the pre-cache %LOCALAPPDATA%\Adom Bridge\bridges\kicad folder; I will make resume/spawn refuse that folder whenever bridges-cache/ exists and list it as 'ignored: legacy folder' the way #161 lists stray cache subfolders, watch the child for the first seconds after spawn so a bind failure reports status failed with its stderr instead of running, and add pid + exePath to bridge_list rows. Your remediation (move bridges\kicad aside) is the right manual fix meanwhile; I will check the other boxes for the same folder.

John Lauer · 1mo ago

Fixed in insiders 2.1.134, all three asks.

1. The bundled seed is never a substitute for an exe-kind cache manifest. The path you hit was start_kicad_bridge: the cache manifest declared spawn.kind: exe, the exe was missing mid-swap, and the dedicated start path fell back to the bundled server.py (the 0.9.65 seed), which bound the persisted port and answered every kicad_* verb while bridge_list named the cache build. That branch (and Fusion's twin) now refuses: status: error, a spawn refused: manifest declares spawn.kind exe but <exe> is missing; the bundled seed is not a substitute line in the bridge's lifecycle log, and the verb fails instead of being answered by the wrong code. The seed is used only when no cache manifest exists at all.

2. A dead child is a failed spawn, and a stranger on the port is never "the bridge". Two pieces:

  • try_spawn_and_wait now checks the spawned pid on every health tick; a child that exits before it is healthy returns bridge '<name>' exited N ms after spawn (pid, image) before answering <health url>; a bind failure on :<port> or a crash at startup with the tail of its own log, instead of polling the port for 30 s and scoring whatever answers there as ready.
  • Before a spawn, and before the kicad/fusion request paths SEND a verb, the persisted port's holders are checked by image (netstat + QueryFullProcessImageName; one check per bridge per minute once verified as ours). A holder that is not the bridge's killImageName is a stranger: the request path answers "not running" at once (no 60-130 s timeout against a socket that never replies), the auto-start path runs, and ensure_bridge_running clears the persisted port and allocates a new one rather than spawning a child into a bind failure. Logged as PORT-MOVE in startup.log and in the bridge's lifecycle log. A manifest-pinned port (pup's 8851) cannot move and gets the early-exit report instead.

3. bridge_list rows already carry livePids and runningImage (2.1.72, #162), which is the pid + image ab believes serves the bridge; runningImage vs expectedImage mismatch sets entryMismatch. I did not add a separate exePath; entrypoint on the row is the path ab spawns.

Proof (arav-rog on 2.1.134):

(a) cache exe hidden, bridge killed, kicad_status:
    -> no python 0.9.65 spawned; lifecycle log:
       spawn refused: manifest declares spawn.kind exe but ...ridges-cache\kicad\kicad-bridge.exe is missing; the bundled seed is not a substitute (wiki #186)
    -> verb fails (bridge_not_listening, retry hint) instead of being answered by the wrong code

(b) bridge killed, a dummy TcpListener holding kicad's persisted port 51624, kicad_status:
    2.1.133: 70.7 s, "KiCad bridge request failed: error sending request" (sent to the stranger)
    2.1.134: 1.9 s, bridge_starting; lifecycle log:
       port 51624 is held by a process that is not kicad-bridge.exe (pids [5616]); not sending the verb to it (wiki #186)
       port 51624 is held by a process that is not kicad-bridge.exe (pids [5616]); re-picking a port instead of spawning into a bind failure (wiki #186)
       spawned process pid 18440 (kicad-bridge.exe)
    bridge_list after: kicad port 57113, livePids [18440], running; next kicad_status 1.8 s, bridgeVersion 1.0.30
    startup.log: PORT-MOVE: bridge 'kicad' leaves port 51624: port 51624 is held by a process that is not kicad-bridge.exe ...

Your remediation (moving bridges\kicad aside) is still right for a box that already has the 0.9.65 process running; from 2.1.134 on, ab will not start it in the first place, and the port check kills the "verbs go to the wrong process" symptom even if something else ends up on the port.

John Lauer closed this · 1mo ago

Log in to reply.