Fix: Upgrades fail with launchctl EIO (bootout race)

authbridge/cmd/abctl/cmd_service.go

@@ -29,8 +29,12 @@ const (
 	systemdUnit  = "cortex.service"
 	// maxLogBytes bounds one generation of proxy.log; rotateLog keeps one previous
 	// file, so the pair tops out near twice this.
-	maxLogBytes  = 8 << 20
-	serviceUsage = `abctl service — keep Cortex running across crashes and logins
+	maxLogBytes = 8 << 20
+	// serviceBootoutTimeout bounds the wait for a previous job to leave the domain.
+	// Longer than the supervisor's own teardown: it SIGTERMs the proxy, allows its 15s
+	// graceful shutdown, then insists at 20s.
+	serviceBootoutTimeout = 30 * time.Second
+	serviceUsage          = `abctl service — keep Cortex running across crashes and logins
 
 Usage:
   abctl service install   [--yes] [--config PATH]
@@ -334,7 +338,7 @@ func serviceInstall(p servicePaths, yes bool, stdout, stderr io.Writer) int {
 		fmt.Fprintf(stdout, "Wrote %s\n", p.unitFile)
 	}
 
-	if err := loadService(p); errors.Is(err, errLingerUnavailable) {
+	if err := loadService(p, stdout); errors.Is(err, errLingerUnavailable) {
 		// The unit IS loaded, so this is a caveat rather than a failure: keep going,
 		// but never claim it survives a logout.
 		fmt.Fprintf(stderr, "abctl: %v\n", err)
@@ -495,7 +499,7 @@ func serviceControl(action string, p servicePaths, stdout, stderr io.Writer) int
 		// umask — measured at 0644, which silently undid the 0600 this sets.
 		tightenLog(p.logFile, stderr)
 	}
-	if err := controlService(action, p); err != nil {
+	if err := controlService(action, p, stdout); err != nil {
 		fmt.Fprintf(stderr, "abctl: %v\n", err)
 		return 1
 	}

authbridge/cmd/abctl/cmd_service_bootout_test.go

@@ -0,0 +1,199 @@
+package main
+
+import (
+	"bytes"
+	"os"
+	"os/exec"
+	"path/filepath"
+	"runtime"
+	"strconv"
+	"strings"
+	"testing"
+	"time"
+)
+
+// TestWaitBootedOut_RealLaunchd drives real launchctl against a throwaway label,
+// reproducing the failure a real upgrade hit: `launchctl bootout` returns while
+// teardown is still in progress, and bootstrapping into that window fails with
+// "Bootstrap failed: 5: Input/output error". Our own teardown is slow — the supervisor
+// forwards SIGTERM and waits out the proxy's graceful shutdown — so the window is wide
+// enough to lose. A trivial job dies fast enough to hide it, which is why every test
+// starting from nothing, or running uninstall first, passed.
+// TestBootoutWaitIsWiredIn pins the CALL SITE, not just the helper.
+//
+// Verified by mutation: deleting the waitBootedOut call from loadService left this
+// entire suite green — the same shape of gap that let the EIO bug ship. Reading the
+// source is the idiom already used by TestStopIsDurable, and unlike the launchd test
+// below it runs on Linux CI.
+func TestBootoutWaitIsWiredIn(t *testing.T) {
+	src, err := os.ReadFile("cmd_service_platform.go")
+	if err != nil {
+		t.Fatal(err)
+	}
+	body := string(src)
+
+	w := strings.Index(body, "waitBootedOutf(target, serviceBootoutTimeout")
+	if w < 0 {
+		t.Fatal("loadService no longer waits for bootout to complete; " +
+			"an upgrade over a running service will fail with launchctl EIO")
+	}
+	b := strings.Index(body, `"launchctl", "bootstrap"`)
+	if b < 0 {
+		t.Fatal("no bootstrap call found")
+	}
+	if w > b {
+		t.Error("the bootout wait comes AFTER bootstrap; it has to precede it")
+	}
+	// And the bootout whose completion we wait for must still be issued before it.
+	o := strings.Index(body, `"launchctl", "bootout", target`)
+	if o < 0 || o > w {
+		t.Error("bootout is not issued before the wait")
+	}
+}
+
+func TestWaitBootedOut_RealLaunchd(t *testing.T) {
+	// Four skip paths meant this could report success having executed no assertion —
+	// on the very machine a release is built from. ABCTL_LAUNCHD_TESTS=required turns
+	// every skip into a failure, so a release check can prove the race was exercised
+	// rather than hope it was. This bug shipped because a path was never exercised; the
+	// guard against it should not be silently skippable.
+	skip := t.Skipf
+	if os.Getenv("ABCTL_LAUNCHD_TESTS") == "required" {
+		skip = t.Fatalf
+	}
+	if runtime.GOOS != "darwin" {
+		skip("launchd only (GOOS=%s)", runtime.GOOS)
+		return
+	}
+	if _, err := exec.LookPath("launchctl"); err != nil {
+		skip("no launchctl: %v", err)
+		return
+	}
+	uid := strconv.Itoa(os.Getuid())
+	label := "io.rossoctl.cortex.test.bootout"
+	target := "gui/" + uid + "/" + label
+	dir := t.TempDir()
+
+	// A job that is deliberately slow to die, like the supervisor.
+	script := filepath.Join(dir, "slow.sh")
+	if err := os.WriteFile(script,
+		[]byte("#!/bin/sh\ntrap 'sleep 4; exit 0' TERM\nwhile :; do sleep 1; done\n"), 0o700); err != nil { //nolint:gosec
+		t.Fatal(err)
+	}
+	plist := filepath.Join(dir, label+".plist")
+	body := `<?xml version="1.0" encoding="UTF-8"?>
+<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
+<plist version="1.0"><dict>
+  <key>Label</key><string>` + label + `</string>
+  <key>ProgramArguments</key><array><string>` + script + `</string></array>
+  <key>RunAtLoad</key><true/><key>KeepAlive</key><true/>
+</dict></plist>`
+	if err := os.WriteFile(plist, []byte(body), 0o600); err != nil {
+		t.Fatal(err)
+	}
+	t.Cleanup(func() {
+		_ = exec.Command("launchctl", "bootout", target).Run() //nolint:errcheck
+		_ = exec.Command("pkill", "-f", script).Run()          //nolint:errcheck
+	})
+
+	_ = exec.Command("launchctl", "bootout", target).Run() //nolint:errcheck
+	waitBootedOut(target, 10*time.Second)
+	if out, err := exec.Command("launchctl", "bootstrap", "gui/"+uid, plist).CombinedOutput(); err != nil {
+		skip("cannot bootstrap a test agent here: %v: %s", err, out)
+		return
+	}
+	_ = exec.Command("launchctl", "kickstart", "-p", target).Run() //nolint:errcheck
+
+	// The race only exists while a job is actually RUNNING and slow to die. Without
+	// this guard the test passed in 0.07s against a job launchd had never started —
+	// green, and proving nothing. launchd refuses to start agents added mid-session in
+	// some domains (see supervise.go), so skip loudly rather than pass vacuously.
+	running := false
+	for i := 0; i < 20; i++ {
+		out, _ := exec.Command("launchctl", "print", target).CombinedOutput()
+		for _, line := range strings.Split(string(out), "\n") {
+			if strings.Contains(line, "state = running") {
+				running = true
+			}
+		}
+		if running {
+			break
+		}
+		time.Sleep(200 * time.Millisecond)
+	}
+	if !running {
+		skip("launchd would not start the test agent in this domain; cannot exercise the race")
+		return
+	}
+
+	// Tear it down and confirm waitBootedOut does not return until the label is gone.
+	_ = exec.Command("launchctl", "bootout", target).Run() //nolint:errcheck
+	if !waitBootedOut(target, 20*time.Second) {
+		t.Fatal("waitBootedOut timed out; teardown never completed")
+	}
+	// Deliberately NOT asserting how long it waited. That assertion was here and was
+	// flaky: launchd sometimes tears the job down in milliseconds, so "must take at
+	// least a second" failed on a correct implementation. The contract that matters is
+	// the post-condition below — the label is gone, and the bootstrap that used to hit
+	// EIO now succeeds.
+	// The label must really be absent now, which is what makes the next bootstrap safe.
+	if err := exec.Command("launchctl", "print", target).Run(); err == nil {
+		t.Error("waitBootedOut returned true while the label is still in the domain")
+	}
+	// And the bootstrap that previously failed with EIO must now succeed.
+	out, err := exec.Command("launchctl", "bootstrap", "gui/"+uid, plist).CombinedOutput()
+	if err != nil {
+		t.Errorf("bootstrap after waitBootedOut still failed: %v: %s", err, out)
+	}
+	if strings.Contains(string(out), "Input/output error") {
+		t.Errorf("still hitting the EIO race: %s", out)
+	}
+}
+
+// TestWaitGone_Progress covers the progress line deterministically.
+//
+// Up to 30s of silence right after "Setting up the launchd user agent..." is
+// indistinguishable from a hang, and it lands on exactly the people who just hit the
+// EIO failure. Driving waitGone with a fake predicate tests that without needing to
+// hold a real launchd label half-torn-down, which is not something a test can arrange —
+// the first version of this could only skip.
+func TestWaitGone_Progress(t *testing.T) {
+	t.Run("a fast teardown stays silent", func(t *testing.T) {
+		var out bytes.Buffer
+		if !waitGone(2*time.Second, &out, func() bool { return true }) {
+			t.Fatal("reported not-gone for an immediately-gone label")
+		}
+		if out.Len() != 0 {
+			t.Errorf("the common case should print nothing, got: %q", out.String())
+		}
+	})
+
+	t.Run("a slow teardown announces, then confirms", func(t *testing.T) {
+		var out bytes.Buffer
+		start := time.Now()
+		ok := waitGone(10*time.Second, &out, func() bool { return time.Since(start) > 1500*time.Millisecond })
+		if !ok {
+			t.Fatal("gave up on a label that did go away")
+		}
+		got := out.String()
+		if !strings.Contains(got, "Waiting for the previous Cortex to stop") {
+			t.Errorf("no progress line during a slow teardown: %q", got)
+		}
+		if !strings.Contains(got, "stopped.") {
+			t.Errorf("announced the wait but never confirmed the end: %q", got)
+		}
+	})
+
+	t.Run("a label that never goes away times out", func(t *testing.T) {
+		var out bytes.Buffer
+		if waitGone(300*time.Millisecond, &out, func() bool { return false }) {
+			t.Error("claimed a still-present label was gone")
+		}
+	})
+
+	t.Run("a nil writer is safe", func(t *testing.T) {
+		if !waitGone(2*time.Second, nil, func() bool { return true }) {
+			t.Error("nil progress writer broke the wait")
+		}
+	})
+}

authbridge/cmd/abctl/cmd_service_durable_test.go

@@ -29,7 +29,11 @@ func TestStopIsDurable(t *testing.T) {
 	})
 
 	t.Run("and start clears that disable, or nothing could start again", func(t *testing.T) {
-		if !strings.Contains(body, `"launchctl", "enable", "gui/"+uid+"/"+launchdLabel`) {
+		// Matched loosely on purpose. The precise form was
+		// `"launchctl", "enable", "gui/"+uid+"/"+launchdLabel`, and a later refactor to a
+		// `target` variable broke this assertion while the behaviour was unchanged —
+		// which is the standing cost of reading source instead of driving the code.
+		if !strings.Contains(body, `"launchctl", "enable"`) {
 			t.Error("loadService does not enable; a stop would make every later start fail")
 		}
 	})

authbridge/cmd/abctl/cmd_service_platform.go

@@ -146,19 +146,58 @@ WantedBy=default.target
 `
 }
 
-func loadService(p servicePaths) error {
+func loadService(p servicePaths, progress io.Writer) error {
 	if runtime.GOOS == "darwin" {
 		uid := strconv.Itoa(os.Getuid())
+		target := "gui/" + uid + "/" + launchdLabel
 		// Clear any disable left by `service stop`: a disabled label cannot be
 		// bootstrapped, so without this a stop would make every later start and
 		// install fail for a reason nothing on screen explains.
-		_ = exec.Command("launchctl", "enable", "gui/"+uid+"/"+launchdLabel).Run() //nolint:errcheck
-		// bootout first so a reinstall replaces cleanly; ignore its error, the
-		// service may not be loaded at all.
-		_ = exec.Command("launchctl", "bootout", "gui/"+uid+"/"+launchdLabel).Run() //nolint:errcheck
-		out, err := exec.Command("launchctl", "bootstrap", "gui/"+uid, p.unitFile).CombinedOutput()
-		if err != nil {
-			return fmt.Errorf("launchctl bootstrap failed: %v: %s", err, strings.TrimSpace(string(out)))
+		_ = exec.Command("launchctl", "enable", target).Run() //nolint:errcheck
+
+		// bootout, keeping its output: a REFUSED bootout and a SLOW one both leave the
+		// label in the domain, and telling someone to "try again" is only right for the
+		// slow one. Its error alone is not enough to distinguish them — it also fails
+		// when nothing was loaded, which is the common case — so the output is kept and
+		// only consulted if the label is still there afterwards.
+		bootoutOut, bootoutErr := exec.Command("launchctl", "bootout", target).CombinedOutput()
+
+		// WAIT for it to actually leave the domain. `launchctl bootout` returns before
+		// teardown finishes, and bootstrapping into a domain that still holds the label
+		// fails with "Bootstrap failed: 5: Input/output error" — which is what a real
+		// upgrade produced: the running service could not be replaced, the install
+		// rolled back, and Cortex was left stopped.
+		//
+		// Our teardown is slow on purpose: bootout SIGTERMs the supervisor, which
+		// forwards to the proxy and waits out its 15s graceful shutdown before
+		// insisting. A trivial job dies fast enough to hide this, which is why every
+		// test that started from nothing or ran uninstall first passed.
+		if !waitBootedOutf(target, serviceBootoutTimeout, progress) {
+			if bootoutErr != nil && !strings.Contains(string(bootoutOut), "No such process") {
+				return fmt.Errorf("could not remove the previous %s: %v: %s",
+					supervisorName(), bootoutErr, strings.TrimSpace(string(bootoutOut)))
+			}
+			return fmt.Errorf("the previous %s is still shutting down after %s; "+
+				"run `abctl service status`, then try again", supervisorName(), serviceBootoutTimeout)
+		}
+
+		// Retried on EIO, re-checking the domain each time. Without the re-check the
+		// claim that bootstrap is idempotent here would hold for the first attempt
+		// only: an attempt that registers the label and THEN fails leaves the next one
+		// returning "File exists" rather than EIO.
+		for attempt := 1; ; attempt++ {
+			out, err := exec.Command("launchctl", "bootstrap", "gui/"+uid, p.unitFile).CombinedOutput()
+			if err == nil {
+				break
+			}
+			if attempt >= 3 || !strings.Contains(string(out), "Input/output error") {
+				return fmt.Errorf("launchctl bootstrap failed: %v: %s", err, strings.TrimSpace(string(out)))
+			}
+			time.Sleep(time.Duration(attempt) * time.Second)
+			if !waitBootedOutf(target, serviceBootoutTimeout, progress) {
+				return fmt.Errorf("launchctl bootstrap failed and the label is still "+
+					"registered: %v: %s", err, strings.TrimSpace(string(out)))
+			}
 		}
 		// bootstrap REGISTERS the job; it does not reliably start it. Observed on a
 		// real install: the agent loaded, `state = not running`, nothing served, and
@@ -339,7 +378,7 @@ func dialableAddr(addr string) string {
 }
 
 // controlService maps stop/start/restart onto the platform's supervisor.
-func controlService(action string, p servicePaths) error {
+func controlService(action string, p servicePaths, progress io.Writer) error {
 	if runtime.GOOS == "darwin" {
 		target := "gui/" + strconv.Itoa(os.Getuid()) + "/" + launchdLabel
 		switch action {
@@ -362,10 +401,10 @@ func controlService(action string, p servicePaths) error {
 			}
 			return nil
 		case "start":
-			return loadService(p) // loadService clears the disable
+			return loadService(p, progress) // loadService clears the disable
 		default: // restart
 			_ = exec.Command("launchctl", "bootout", target).Run() //nolint:errcheck
-			return loadService(p)
+			return loadService(p, progress)
 		}
 	}
 	if _, err := exec.LookPath("systemctl"); err != nil {
@@ -525,3 +564,52 @@ func unitWriterVersion(unitFile string) string {
 	}
 	return ""
 }
+
+// waitBootedOut polls until the label is gone from its domain.
+//
+// `launchctl bootout` is asynchronous: it returns while teardown is still in progress,
+// and a bootstrap issued in that window fails with EIO. Polling `launchctl print` is
+// the only signal available — a non-zero exit means the label is no longer there.
+func waitBootedOut(target string, d time.Duration) bool {
+	return waitBootedOutf(target, d, nil)
+}
+
+// waitBootedOutf is waitBootedOut with a progress line.
+//
+// Up to 30s of silence right after "Setting up the launchd user agent..." is
+// indistinguishable from a hang, and it lands on exactly the people who just hit the
+// EIO failure this wait exists to prevent. One line after the first second, so a fast
+// teardown — the common case — stays silent.
+func waitBootedOutf(target string, d time.Duration, progress io.Writer) bool {
+	return waitGone(d, progress, func() bool {
+		// A non-zero exit from `launchctl print` means the label is no longer there.
+		return exec.Command("launchctl", "print", target).Run() != nil
+	})
+}
+
+// waitGone polls gone() until it reports true, or d elapses.
+//
+// Split from waitBootedOutf so the progress behaviour is testable without launchd. The
+// first attempt at testing it could only skip — there is no way to hold a real launchd
+// label in a half-torn-down state on demand — and a test that skips is how the bug this
+// wait exists to prevent got shipped in the first place.
+func waitGone(d time.Duration, progress io.Writer, gone func() bool) bool {
+	announced := false
+	start := time.Now()
+	for {
+		if gone() {
+			if announced && progress != nil {
+				fmt.Fprintln(progress, "  ...stopped.")
+			}
+			return true
+		}
+		if !announced && progress != nil && time.Since(start) > time.Second {
+			fmt.Fprintf(progress, "  Waiting for the previous Cortex to stop (up to %s)...\n", d)
+			announced = true
+		}
+		if time.Since(start) > d {
+			return false
+		}
+		time.Sleep(250 * time.Millisecond)
+	}
+}