diff options
Diffstat (limited to 'docs/link-drop-investigation.md')
| -rw-r--r-- | docs/link-drop-investigation.md | 266 |
1 files changed, 106 insertions, 160 deletions
diff --git a/docs/link-drop-investigation.md b/docs/link-drop-investigation.md index 807145b..bf7efb4 100644 --- a/docs/link-drop-investigation.md +++ b/docs/link-drop-investigation.md @@ -1,190 +1,136 @@ # Investigation: idle link-socket drops in the multi–Game Boy setup -Status: **open / not root-caused.** This document records what the bug is, what -has been ruled out, the exact conditions under which it reproduces, and the most -promising next steps, so the next debugging session can start cold. +Status: **root-caused (with one honest caveat) and mitigated — drops are now +self-healing.** This document records the original mystery, the follow-up +session that resolved it, and the fixes that shipped. -## TL;DR +## TL;DR (resolution) -When a Game Boy's link port is bridged over a unix socket (`sl0pboy ---serial-sock`), the **link connection gets dropped while the Game Boy is idle** -(sitting at the shell prompt after it has a DHCP lease). The emulator *process -stays alive* — it is the socket that dies, and nothing reconnects, so that GB -goes permanently offline until the emulator is relaunched. +The link socket never "mysteriously dies". Every drop signature we could +produce — and every one we could explain — is the **emulator process dying** +(or, historically, being observed wrongly). The kill vectors are mundane but +were all *silent*, which made them look like spooky socket death: -It is **not** a gbos crash, **not** a gbos poweroff, and **not** caused by the -recent KGetc/net_pump change (the pre-change ROM drops too). It only happens -when the link is **idle** (no packets flowing); a busy link stays up. +1. **SIGPIPE (proven, fixed).** In `--serial-sock` mode the emulator never + ignored SIGPIPE. gbos mirrors every console byte to the link (`KPutc` → + rSC=$81), so the moment the hub restarts or hiccups, the next prompt echo + `write()` killed the whole emulator with the default SIGPIPE action — + no stderr, no message, nothing. A hub restart would cascade-kill every GB. +2. **Terminal death / HUP / stray quit keys (windowed, the user's setup).** + The windowed emulator is a child of its terminal session. An **idle** SSH + session dropping (NAT/firewall idle timeout — the classic), a closed + terminal tab (SIGHUP), or a stray `q` / Ctrl-C reaching `input_poll` + (ISIG is off; `q` is a documented quit key) all exit the emulator cleanly + and near-silently. **This precisely reproduces the "drops only when idle" + correlation: a busy link means a busy SSH session, which doesn't idle out.** +3. **Guest `$ED` poweroff (possible, now visible).** The illegal opcode `$ED` + requests a clean emulator exit and used to print *nothing*. Any gbos crash + that walked into byte `$ED` would look exactly like a silent socket death. +4. **Observation artifacts (the spawn-mode ghost — see caveat).** -## Symptom +Verified end-to-end: killing the emulator produces exactly the reported +signature — `[gbhub] GBn (10.0.0.x) left` with a clean EOF, hub alive. -- Hub (`tools/gbhub`) logs `[gbhub] GB0 (10.0.0.2) left`, i.e. its per-GB reader - thread's `conn.recv()` returned empty (or raised and was caught). -- In the user's interactive session the GB then appeared to "rejoin" repeatedly — - that was the user relaunching `gbjoin` after each drop (see "No recovery"). -- `ping <that GB>` from another GB fails because the target is offline. +## The caveat: the spawn-mode drop did not reproduce under instrumentation -## Architecture recap (so the pieces are named) +The original session reported `sudo tools/gbhub 1 ""` reliably dropping an +idle GB with **both** processes alive. A follow-up session attempted to +reproduce this for over an hour with heavy instrumentation: -- Each Game Boy = one `sl0pboy` emulator. Its **link/serial port** is wired to a - **unix stream socket** via `--serial-sock PATH` (emulator connects as client; - `serial_connect()` in `src/main.c`, retried ~1s at startup **only**). -- `tools/gbhub` is a virtual switch/router/DHCP. It `accept()`s each GB's socket, - runs a per-GB reader thread (`gb_reader`) that SLIP-decodes frames and routes - them, answers DHCP, and NATs external traffic out a TUN. - - **daemon mode** (`gbhub --daemon`): hub is its own process; emulators are - launched separately (`tools/gbjoin`). - - **spawn mode** (`gbhub N`): hub *and* the emulator child processes live in - one process. -- The GB's kernel serial RX (`net_getbyte_nb`, `gb.c` rSC=0x80 path) does a - non-blocking `read()` of 1 byte per poll; TX (`rSC=0x81`) does a non-blocking - `write()` of 1 byte and ignores errors. +- 25 fresh-boot spawn rounds (2 GBs + ping traffic, 30s each): no drop. +- Three long idle soaks (10–15 min, 1 GB): no drop — under `strace`, under an + `LD_PRELOAD` shim logging every `close()`/`shutdown()` with backtraces and + every non-EAGAIN serial-fd errno, and bare. +- A windowed (sixel) emulator under a synthetic pty, including a 2-minute + full terminal stall: survived, link intact. -## What it is NOT (ruled out this session) +Meanwhile, the follow-up session *itself* fell into every observation trap +that plausibly produced the original "socket died, processes alive" claim: -- **Not a gbos crash.** Emulator stderr is clean (`Loaded 'GBOS' ... / link port - <-> ...` and nothing else). No fault/opcode message. -- **Not a gbos poweroff via readc EOF.** Instrumented the shell's read loop to - print every byte and to not `poweroff()` on EOF — no `EOF` byte was ever read, - and the GB still left. So the shell is not powering off. -- **Not the emulator process exiting.** Logged `Popen.poll()` — it stays `None` - (process alive) after "left". The *socket* died, not the process. -- **Not the recent KGetc/net_pump change.** Stashing that change and rebuilding - the previous gbos still drops in spawn mode. Pre-existing. -- **Not the TUN, NAT, `--uncapped`, the per-GB ROM copy, or a stale battery - `.sav`.** A standalone harness that adds each of these one at a time keeps the - GB up (see matrix). -- **Not gbhub's `while all(e.poll())` main loop.** Replacing it with a plain - sleep did not stop the drop. -- **Not gbhub's per-line `stderr.flush()` console logging.** Disabling it did not - stop the drop. +- `pkill -f`/`pgrep -f` patterns matching the *observer's own shell*, killing + the test mid-flight (looks like a spontaneous drop). +- Root-owned **stray emulators** surviving unprivileged pkill across test + rounds — a later `pgrep`/`poll()` check can examine a *stale* process and + conclude "the emulator is still alive" while the current one died. +- Sandbox command aborts killing the hub's process group while + `start_new_session` emulators survive as strays (idle sessions get aborted; + busy ones finish fast — another way "idle" correlates with drops). +- A second gbhub crashing on `gbtun0` EBUSY, with cleanup paths able to + unlink the live hub's socket or NAT rules. -## Where it reproduces (bisection matrix) +Given that no instrumented run ever showed a socket dying while its owner +lived, and that Linux unix-domain sockets have **no idle timeout mechanism at +all**, the working conclusion is that the spawn-mode observations were +process deaths misattributed by tooling. If a drop ever recurs under the new +logging (below), it will be attributable in minutes, not sessions. -| Setup | Idle GB result | -|---|---| -| Minimal harness: one Python proc spawns the emulator **and** reads its socket; no TUN; capped | **survives** | -| Harness + TUN + a `tun_reader` (nothing gets forwarded to the GB at idle) | **survives** | -| Harness + TUN + NAT (`ip_forward` + masquerade) + `--uncapped` | **survives** | -| Harness + fresh ROM copy (no `.sav`) | **survives** | -| `gbhub --daemon` + **headless** emulators as separate processes (`hubtest.py`) | **survives** ✅ | -| `gbhub N` **spawn mode** (emulators are children of the hub, one process) | **drops when idle** ❌ | -| `gbhub --daemon` + **windowed** `gbjoin` (the user's real setup) | **drops when idle** ❌ | +## Fixes shipped -Two important facts fall out of this: +### Emulator (`~/dev/gbc`) -1. **`daemon + headless` is the only combination that is reliably stable.** -2. There appear to be **two independent triggers**, because: - - spawn mode drops with **headless** emulators, and - - daemon mode drops with **windowed** emulators, - but `daemon + headless` does not. +- **Link auto-reconnect** (`gb.c`): in `--serial-sock` mode, EOF on read or + EPIPE/ECONNRESET/ENOTCONN/EBADF on either direction marks the link dead, + closes the fd, and retries `connect()` every 500ms from the serial poll + path (the guest polls constantly, so this needs no extra plumbing). RX + stays "pending" while down (`serial_no_eof` semantics), so gbos just sees + a quiet link that comes back. Logs `link socket lost / reconnected`. +- **SIGPIPE ignored** in `--serial-sock` mode (`main.c`) — a dead bridge + degrades the link instead of killing the Game Boy. +- **`$ED` poweroff now logs** pc/registers to stderr (`cpu.c`), and the + headless loop logs *why* it exited (guest poweroff vs signal). No more + silent exits. -## The frustrating part +### Hub (`tools/gbhub`) -The standalone harness `edbg2.py` — which, like spawn-mode gbhub, spawns the -emulator **and** reads its socket in the **same process**, with TUN+NAT+uncapped — -**survives**. So the drop is *not* simply "the process that reads the socket is -also the emulator's parent." Yet gbhub spawn mode, which is functionally the -same, **drops**. Every difference I could find between them was eliminated -without changing the outcome: +- `gb_reader` distinguishes a clean EOF from an exception and logs which + (`left (eof)` vs `left (ConnectionResetError: ...)`), with timestamps on + join/leave for correlating against SSH/terminal events. +- Spawn mode keeps each emulator's stderr in `/tmp/gbhub_<n>.err` instead of + discarding it — postmortems now have the emulator's side of the story. +- A second `gbhub` now exits with a clear "another gbhub is already running?" + message instead of an ioctl traceback (and cannot damage the live hub). -- Same emulator argv. -- Same DHCP reply bytes (gbhub `_dreply` == harness `dreply`, byte-for-byte). -- Same TUN/NAT. -- Console-logging removed, poll-loop removed — still drops. +### Behavior after a drop (any cause) -So the specific difference that flips gbhub-spawn from "survives" to "drops" was -**not isolated**. Likewise the windowed-vs-headless difference in daemon mode was -not isolated (couldn't be driven in the sandbox — no interactive TTY). +Emulator killed → relaunch it (`gbjoin`), it rejoins as before. +Hub killed/restarted → all emulators reconnect within ~1s, re-register, and +keep their IPs (the pool hands the lowest free octet back, and the hub +routes by its own per-connection IP assignment, so the guest's existing +lease keeps working without a fresh DHCP exchange). Verified by SIGKILLing +the hub, restarting it, and pinging the reconnected GB. -## Key behavioral clue +## Still worth doing (not blocking) -Drops happen **only when the link is idle**. When the GB is doing something over -the network (answering pings via `netd` or the prompt-pump, running `ping`/ -`wget`), the link stays up. This strongly implicates the **quiet-socket** path: -the GB spinning `net_getbyte_nb` (many 1-byte non-blocking `read()`s/sec on a -socket with no data) and/or the hub's reader thread blocked in `recv()` with -nothing arriving. +- gbos-side periodic DHCP renewal (or "link came back" re-DHCP) so IP + assignment survives pool reshuffles when *multiple* GBs reconnect out of + order. +- The windowed main loop ignores `gb->poweroff` (only headless honors it); + harmless, but inconsistent. +- Consider making `q` a less accidental quit (e.g. require `qq` or Ctrl-C + twice) for long-running windowed sessions over SSH; an idle-timeout HUP + can't be fixed client-side, but `ServerAliveInterval`/`tmux` on the + streaming box sidesteps it operationally. -## No recovery (makes every drop fatal) +## Repro/diagnosis pointers (current tooling) -Independent of the cause, there is currently **no self-healing**: - -- The emulator's `serial_connect()` runs **once** at startup; a dead socket is - never reconnected (reads/writes just fail silently; `serial_no_eof` keeps RX - "pending" forever). -- gbos runs `dhcp` **once** at boot; no lease renewal, no "link back" detection. -- So a drop = offline until manual relaunch. This is why the user saw constant - "churn." - -(Adding auto-reconnect in the emulator + a periodic lease renewer in gbos would -make drops a ~1s blip and is worth doing regardless — but it is a *mitigation*, -not the fix.) - -## The hard constraint any theory must satisfy - -**Both processes stay alive, but the socket dies.** The emulator's `poll()` stays -`None` (process alive) and the hub is alive (it logs "left"), yet the hub's -`recv()` returns empty - meaning the emulator's *write half* of the link socket -was closed. Nothing in `gb.c`/`main.c` closes that fd, and the emulator never -exits. So the precise question is: **what closes/resets the emulator-side link fd -without the emulator process exiting?** - -Note this *weakens* a naive `SIGPIPE` theory: an unignored `SIGPIPE` would -*terminate* the emulator, which contradicts "process alive" (unless that -observation is racy). Worth confirming, but not a clean fit. - -## Hypotheses still on the table - -1. **A socket syscall/errno we simply haven't observed.** Given the constraint - above, stop guessing and `strace` it (see next steps). Look for an unexpected - `close(fd)`, an `ECONNRESET`/`EPIPE` on `read`/`write`, or a faulting `write`. - Also check whether the emulator installs `SIG_IGN` for `SIGPIPE` and whether a - signal is actually delivered. -2. **Hub `recv()` raising, not a clean peer-close.** `gb_reader` does - `except Exception: chunk = None`, so an exception (e.g. `ConnectionResetError`) - is reported identically to a clean EOF. The two need to be distinguished. -3. **High-frequency 1-byte reads** on the unix socket interacting badly with the - emulator's serial state machine or the socket under specific scheduling. -4. **Windowed path** (`daemon + gbjoin`): the non-headless main loop - (`render_frame` sixel to stdout + `input_poll` on stdin + paced 59.73fps) may - starve serial servicing or interact with a slow terminal; needs a real TTY to - reproduce. - -## Next diagnostic steps (in priority order) - -1. **Check/ignore SIGPIPE in the emulator.** Add `signal(SIGPIPE, SIG_IGN)` at - startup and re-test spawn mode. If the drop stops, hypothesis (1) is confirmed. - (Cheap, high-value.) -2. **`strace -f -e trace=network,read,write,close` the emulator** during a spawn- - mode idle drop; find the exact syscall + errno at the moment the socket dies - (EPIPE/ECONNRESET/close). This should end the guessing. -3. **Distinguish EOF vs reset in the hub.** In `gb_reader`, log the exception type - separately from a clean empty `recv()`. Tells us who closed and why. -4. **Reproduce the windowed case on a real terminal** (outside the sandbox): - `sudo tools/gbhub --daemon` + `tools/gbjoin` in another terminal; watch - whether the emulator window closes (process exits) or the link goes quiet - (socket drop). Note anything on stderr. -5. If (1)/(2) implicate the write path, consider making the emulator's serial - socket writes tolerate back-pressure explicitly (drop-on-EAGAIN is already the - intent, but make sure a full buffer / peer-gone can't escalate). - -## Repro / harness pointers - -- Fails: `sudo tools/gbhub 1 ""` (single idle GB, spawn mode) — `GB0 ... left`. -- Fails: `sudo tools/gbhub 2 "" "ping 10.0.0.2"` is *racy* now — GB0 sometimes - drops before GB1's ping lands. -- Survives: daemon mode with headless emulators launched separately (the shape of - the throwaway `hubtest.py` used this session: spawn `gbhub --daemon` as one - process, then two `sl0pboy --headless --uncapped --serial-sock /tmp/gbhub.sock` - as separate children; both idle GBs keep their leases). +- Hub log now answers "who closed, and how": `left (eof)` = peer's fd closed + (process exit or explicit close); `left (SomeError: ...)` = hub-side error. +- Emulator stderr (`/tmp/gbhub_<n>.err` in spawn mode) now answers "why did + the emulator stop": `poweroff opcode $ED at pc=...`, `headless loop exit: + signal`, `link socket lost/reconnected`. +- For deeper hunts, the session's `LD_PRELOAD` fd-spy approach (log + `close`/`shutdown` with backtraces, plus unusual errno on the serial fd) + is cheap and does not perturb timing the way `strace` does — `strace -p` + intercepts *every* syscall even when filtered, which throttles an + `--uncapped` emulator badly. ## Relevant code -- Emulator link socket: `~/dev/gbc/src/main.c` (`serial_connect`, `--serial-sock` - wiring) and `~/dev/gbc/src/gb.c` (rSC=0x80 RX / rSC=0x81 TX, `serial_no_eof`). +- Emulator link socket + reconnect: `~/dev/gbc/src/main.c` (`serial_connect`, + `--serial-sock` wiring, SIGPIPE) and `~/dev/gbc/src/gb.c` (`serial_check`, + `serial_mark_dead`, rSC=$80/$81 paths). - Hub reader/router/DHCP: `~/dev/gbos/tools/gbhub` (`gb_reader`, `route`, - `_dreply`, `tun_reader`). + `_dreply`, `tun_reader`, `net_setup` collision guard). - GB kernel serial/net pump: `~/dev/gbos/src/socket.asm` (`net_getbyte_nb`, `net_putbyte`, `net_pump`) and console pump in `~/dev/gbos/src/syscall.asm` (`KGetc`). |