diff --git a/authbridge/cmd/abctl/cmd_service.go b/authbridge/cmd/abctl/cmd_service.go index 1e58cf09..304c84f5 100644 --- a/authbridge/cmd/abctl/cmd_service.go +++ b/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 } diff --git a/authbridge/cmd/abctl/cmd_service_bootout_test.go b/authbridge/cmd/abctl/cmd_service_bootout_test.go new file mode 100644 index 00000000..96556326 --- /dev/null +++ b/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 := ` + + + Label` + label + ` + ProgramArguments` + script + ` + RunAtLoadKeepAlive +` + 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") + } + }) +} diff --git a/authbridge/cmd/abctl/cmd_service_durable_test.go b/authbridge/cmd/abctl/cmd_service_durable_test.go index 4286791d..39c817b7 100644 --- a/authbridge/cmd/abctl/cmd_service_durable_test.go +++ b/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") } }) diff --git a/authbridge/cmd/abctl/cmd_service_platform.go b/authbridge/cmd/abctl/cmd_service_platform.go index 090a146d..f8422dcf 100644 --- a/authbridge/cmd/abctl/cmd_service_platform.go +++ b/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) + } +}