|

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
 # ============================================================================