supervisor: fix bug 003 — spurious exit=-1 on first-boot exec race
supervisor: fix bug 003 — spurious exit=-1 on first-boot exec race Two distinct defects produced the alarming exit=-1 first-boot reports: A. Exec robustness / silent failure. Under first-boot I/O contention the child's exec of a valid start command could transiently fail; the child then exited silently, leaving an empty per-service log. The child now retries process_exec (5x, 100ms backoff) and, on final failure, records the reason to both the per-service log (fd 2, survives privilege drop) and a new central /var/log/zyginit/zyginit.log (sup_log), then exits 127. B. Reap-race reconciliation (the actual source of -1). The contract-empty bundle-fd event can beat the child's exit-status posting; handle_contract_event committed the -1 'unresolved code' sentinel and tore down tracking, after which the catch-all reaper discarded the real code. It now defers when there is no hint, no resolvable code yet, and a child is still tracked (rt.pid > 0), so the unconditional reap_children re-dispatches with the true exit code within ~1s. Fixes 127->-1 masking AND the false-positive where an exit-0 oneshot that lost the race was reported FAILED. Adds integration Suite 9b (spawn-failure capture); 97/97 tests pass. Defect B rides the Hammerhead contract path (not exercised by Linux stubs) and awaits an hh-alpha first-boot to confirm in situ.
Author:
Chris Tusa <chris.tusa@leafscale.com>
Date:
Jul 20, 2026 21:07
Changeset:
3f1d7f14d5e09f868ac89f19bfd828c7f0ad9df2
Branch:
default
Diff
diff -r 71b8fd133c85 -r 3f1d7f14d5e0 bugs/003-supervisor-exec-race-first-boot-exit-minus-1.md --- a/bugs/003-supervisor-exec-race-first-boot-exit-minus-1.md Mon Jul 20 21:07:33 2026 -0500 +++ b/bugs/003-supervisor-exec-race-first-boot-exit-minus-1.md Mon Jul 20 21:07:44 2026 -0500 @@ -80,3 +80,41 @@ `hh-deploy create` first boots on the hh-alpha VMs (pc-i440fx + OVMF, no ACPI hotplug controller). Cross-ref Hammerhead memory `zyginit-service-empty-path` (the 2026-06-08 boot probe that first characterized the transient stat() miss). + +## Resolution (2026-07-20, zyginit 0.2.6-dev) + +Investigation found `exit=-1` was **not** an exec-failure code (a real exec +failure exits **127**); it is the "could not resolve an exit code" sentinel. +Two distinct defects were fixed in `src/supervisor.reef`: + +- **Defect A — exec robustness + no silent failure.** The service child now + retries `process_exec` a bounded number of times (`EXEC_MAX_ATTEMPTS` = 5, + `EXEC_RETRY_DELAY_MS` = 100ms) to ride out the transient first-boot + stat()/exec miss. When every attempt fails, the child records the failure to + **both** its per-service `<name>.log` (via fd 2, which survives a privilege + drop) **and** the new central `zyginit.log`, then exits 127. This removes the + "failed with an empty log" symptom. Errno is not exposed by the Reef stdlib + `process_exec`, so the retry is a blind bounded retry rather than + errno-selective — a genuinely-missing command still fails all attempts. + +- **Defect B — reap-race reconciliation (the actual source of `-1`).** In the + poll loop the contract-empty event (bundle fd) can beat the child's + exit-status posting. `handle_contract_event` used to commit the `-1` sentinel + and tear down tracking, after which the catch-all reaper discarded the real + code. It now **defers** when there is no hint, no resolvable code yet, and a + child is still tracked (`rt.pid > 0`), leaving `rt.pid` + the contract map + intact so the unconditional `reap_children` re-dispatches with the true code + within ~1s. This fixes both the 127→-1 masking **and** the independent + false-positive where an exit-0 oneshot that lost the race was reported FAILED. + +New central operational log: `/var/log/zyginit/zyginit.log` (`sup_log`), +distinct from the per-service logs. No new report state/label was added +(intentionally — the exit code plumbing now carries the truth). + +Verified on Linux (non-contract path) by integration suite +(`tests/integration/run_tests.sh`, Suite 9b "Spawn-failure capture (bug 003)", +97/97 passing): a service pointing at a missing binary now populates both logs +and is reported `failed` (never `exit=-1`). **Defect B rides the Hammerhead +contract path, which the Linux stubs don't exercise — it still needs a fresh +`hh-deploy create` first-boot on an hh-alpha VM to confirm in situ before this +bug is archived.** diff -r 71b8fd133c85 -r 3f1d7f14d5e0 src/supervisor.reef --- a/src/supervisor.reef Mon Jul 20 21:07:33 2026 -0500 +++ b/src/supervisor.reef Mon Jul 20 21:07:44 2026 -0500 @@ -113,6 +113,42 @@ return sysenv.get_env_or("ZYGINIT_LOG_DIR", "/var/log/zyginit") end LOG_DIR +// Central operational log for the supervisor itself (as opposed to the +// per-service <name>.log files). Records events that would otherwise vanish +// — most importantly spawn failures, where the service child never runs and +// so writes nothing to its own log. See bug 003. +fn ZYGINIT_LOG_PATH(): string + return str.concat(LOG_DIR(), "/zyginit.log") +end ZYGINIT_LOG_PATH + +// Append a single timestamped line to the central zyginit log. Best-effort: +// any failure (dir missing, no space, priv-dropped child) is swallowed so +// logging never blocks or aborts the supervisor. Uses only fd syscalls, so +// it is safe to call from a forked child before exec. +proc sup_log(msg: string) + let flags = fd.O_WRONLY() + fd.O_CREAT() + fd.O_APPEND() + let f = fd.fd_open(ZYGINIT_LOG_PATH(), flags, 420) + if f >= 0 + let line = str.concat(str.concat("[", int_to_str(time.time_now())), + str.concat("] ", str.concat(msg, "\n"))) + let _ = fd.fd_write(f, line) + let _2 = fd.fd_close(f) + end if +end sup_log + +// Exec retry policy for service start commands. On a fresh first boot, +// devfsadm + ZFS-pool-finalize I/O contention can make a stat()/exec of the +// start command (or its #! interpreter) transiently fail even for a valid, +// executable, absolute path. A bounded retry rides out the transient miss; a +// genuinely-missing command still fails every attempt. See bug 003. +fn EXEC_MAX_ATTEMPTS(): int + return 5 +end EXEC_MAX_ATTEMPTS + +fn EXEC_RETRY_DELAY_MS(): int + return 100 +end EXEC_RETRY_DELAY_MS + // Privilege separation FFI wrappers extern "C" fn zyginit_getuid_by_name(name: string): int extern "C" fn zyginit_getgid_by_username(name: string): int @@ -439,6 +475,7 @@ rt.state = STATE_FAILED() table.runtimes[idx] = rt ui.ui_event_failed(name, 0 - 1, 0) + sup_log(str.concat(name, ": fork failed")) if ui.ui_mode() == ui.MODE_PLAIN() println("supervisor: fork failed for " + name) end if @@ -545,10 +582,36 @@ args[a] = parts[a] a = a + 1 end while - process.process_exec(program, args) + + // Retry the exec a bounded number of times. process_exec only + // returns when the exec itself failed (the process image was + // never replaced), so each loop iteration is a fresh attempt. + // This absorbs the transient first-boot stat()/exec miss under + // I/O pressure without masking a genuinely-missing command, + // which fails every attempt and falls through to exit 127. + mut attempt = 0 + while attempt < EXEC_MAX_ATTEMPTS() + process.process_exec(program, args) + attempt = attempt + 1 + if attempt < EXEC_MAX_ATTEMPTS() + clock.sleep_millis(EXEC_RETRY_DELAY_MS()) + end if + end while end if - // exec failed + // Every exec attempt failed — the start command never ran. Record it + // loudly instead of vanishing with an empty log (the bug-003 symptom): + // - fd 2 → per-service <name>.log; the fd was opened as root before + // any privilege drop, so this write survives a dropped-priv child. + // - central zyginit.log via sup_log (best-effort; works while root). + // Then exit 127 ("command not found" convention) so the parent's + // exit-code plumbing reports a real code rather than the -1 sentinel. + let fail_msg = str.concat(str.concat(name, ": exec failed for '"), + str.concat(cmd, + str.concat("' after ", + str.concat(int_to_str(EXEC_MAX_ATTEMPTS()), " attempts")))) + let _ = fd.fd_write(2, str.concat(fail_msg, "\n")) + sup_log(fail_msg) process.exit_now(127) end if @@ -710,6 +773,25 @@ end if end if + // Reap-race reconciliation (Hammerhead contract path, bug 003). + // The contract-empty event on the bundle fd can arrive before the + // child's exit status has been posted for reaping. When that happens + // we have no hint AND try_wait above could not resolve a code, yet a + // child is still tracked (rt.pid > 0). Committing the -1 sentinel here + // would (a) misreport a real exit code — a 127 spawn failure surfaces + // as -1 — and (b) flip an exit-0 oneshot into a spurious FAILED. Worse, + // this handler would then clear rt.pid and the contract map, so the + // catch-all reaper later swallows the true code with nowhere to route + // it. Defer instead: leave rt.pid and the contract mapping intact and + // return. reap_children runs unconditionally every poll iteration and + // re-dispatches this contract with the real exit code (hint >= 0) + // within ~1s. A daemon that already completed its daemonize handshake + // has rt.pid == -1 here, so its genuine crash (code truly unknown) is + // NOT deferred and flows through the logic below as before. + if hint_exit_code < 0 and exit_code < 0 and rt.pid > 0 + return + end if + let svc_type = config.svc_type(def) // Task: may run for any duration. Exit 0 = STOPPED (counts as online). diff -r 71b8fd133c85 -r 3f1d7f14d5e0 tests/integration/run_tests.sh --- a/tests/integration/run_tests.sh Mon Jul 20 21:07:33 2026 -0500 +++ b/tests/integration/run_tests.sh Mon Jul 20 21:07:44 2026 -0500 @@ -815,6 +815,50 @@ stop_daemon # ============================================================================ +# Test Suite 9b: Spawn-failure capture (bug 003) +# ============================================================================ +# +# When a service's start command cannot be exec'd (missing/unrunnable), +# the supervisor must NOT let the service vanish silently with an empty log. +# The child retries the exec a few times, then records the spawn failure to +# both the per-service log (fd 2) and the central zyginit.log before exiting. + +section "Spawn-failure capture (bug 003)" + +rm -rf "$CONFIG_DIR" "$LOG_DIR" +mkdir -p "$CONFIG_DIR" "$ENABLED_DIR" + +# Start command points at a path that does not exist — exec always fails. +create_service "spawn-fail" "oneshot" "/nonexistent/zyginit-bug003-missing --flag" +enable_service "spawn-fail" + +start_daemon + +# Child retries the exec (5 x 100ms) before giving up, so allow settle time. +sleep 3 + +# Central zyginit log must exist and record the spawn failure. +if [ -f "$LOG_DIR/zyginit.log" ]; then + pass "spawn-fail: central zyginit.log created" +else + fail "spawn-fail: central zyginit.log created" "file at $LOG_DIR/zyginit.log" "not found" +fi +central_content=$(cat "$LOG_DIR/zyginit.log" 2>/dev/null) +assert_contains "$central_content" "exec failed" "spawn-fail: central log records exec failure" +assert_contains "$central_content" "spawn-fail" "spawn-fail: central log names the service" + +# The per-service log must NOT be empty (the bug-003 symptom was an empty log). +perservice_content=$(cat "$LOG_DIR/spawn-fail.log" 2>/dev/null) +assert_contains "$perservice_content" "exec failed" "spawn-fail: per-service log records exec failure" + +# The service is reported failed (exit 127), never as exit=-1. +output=$(zygctl status spawn-fail) +assert_contains "$output" "failed" "spawn-fail: service reported failed" +assert_not_contains "$output" "exit=-1" "spawn-fail: not reported as exit=-1" + +stop_daemon + +# ============================================================================ # Test Suite 10: zygctl replace — command parsing and state-file write # ============================================================================