From 8633e7e0d532485d041f1ff9c2809e53465a61e4 Mon Sep 17 00:00:00 2001 From: Hai Huang Date: Fri, 4 Sep 2026 16:55:55 -0400 Subject: [PATCH 1/2] =?UTF-8?q?fix:=20Wait=20for=20bootout=20before=20boot?= =?UTF-8?q?strap=20=E2=80=94=20upgrades=20were=20failing?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit v0.7.0-alpha.6 cannot upgrade an existing install. Reported from a real run: Setting up the launchd user agent... abctl: launchctl bootstrap failed: exit status 5: Bootstrap failed: 5: Input/output error error: could not set up the service (exit 1). Cortex is NOT running. `launchctl bootout` returns before the job has left the domain, and bootstrapping into that window fails with EIO. Reproduced directly against a throwaway label: bootout followed immediately by bootstrap gives `rc=5 Input/output error` when the job is slow to die, and succeeds when it dies instantly. Slow to die is us, by design: bootout SIGTERMs the supervisor, which forwards to the proxy and waits out its 15s graceful shutdown before insisting. So the window is wide enough to lose reliably — which is why this hits every existing user and no test. Every end-to-end run I did either started from nothing or ran `service uninstall` first, so none of them exercised install-over-a-running-service. That is the upgrade path, and it is the only path an existing user takes. The gap was in what I chose to test, not in the testing. loadService now polls until the label is actually gone (30s cap, longer than the supervisor's own 20s teardown) and reports a clear error if it never does, rather than handing back launchd's EIO. Bootstrap additionally retries up to three times on EIO, to close the race inside the window as well as the window itself. Darwin only; systemd's enable/disable does not have this failure mode and its branch is untouched. Verified: reinstalling over a running service now succeeds twice in a row, healthy both times, on a label-isolated build. The test drives real launchctl and skips when launchd will not start the fixture — it first passed in 0.07s against a job that had never run, green and proving nothing, so it now checks for `state = running` and skips loudly instead. It also asserted that the wait took at least a second; that was flaky, because launchd sometimes tears a job down in milliseconds, so a correct implementation failed. Removed. What it pins is the post-condition: the label is gone, and the bootstrap that used to hit EIO succeeds. Assisted-By: Claude (Anthropic AI) Signed-off-by: Hai Huang --- authbridge/cmd/abctl/cmd_service.go | 8 +- .../cmd/abctl/cmd_service_bootout_test.go | 105 ++++++++++++++++++ authbridge/cmd/abctl/cmd_service_platform.go | 51 ++++++++- 3 files changed, 159 insertions(+), 5 deletions(-) create mode 100644 authbridge/cmd/abctl/cmd_service_bootout_test.go diff --git a/authbridge/cmd/abctl/cmd_service.go b/authbridge/cmd/abctl/cmd_service.go index 1e58cf09..70512e73 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] 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..daa7ca6d --- /dev/null +++ b/authbridge/cmd/abctl/cmd_service_bootout_test.go @@ -0,0 +1,105 @@ +package main + +import ( + "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. +func TestWaitBootedOut_RealLaunchd(t *testing.T) { + if runtime.GOOS != "darwin" { + t.Skip("launchd only") + } + if _, err := exec.LookPath("launchctl"); err != nil { + t.Skip("no launchctl") + } + 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 { + t.Skipf("cannot bootstrap a test agent here: %v: %s", err, out) + } + _ = 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 { + t.Skip("launchd would not start the test agent in this domain; cannot exercise the race") + } + + // 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) + } +} diff --git a/authbridge/cmd/abctl/cmd_service_platform.go b/authbridge/cmd/abctl/cmd_service_platform.go index 090a146d..904df743 100644 --- a/authbridge/cmd/abctl/cmd_service_platform.go +++ b/authbridge/cmd/abctl/cmd_service_platform.go @@ -156,9 +156,36 @@ func loadService(p servicePaths) error { // 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))) + + // 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 !waitBootedOut("gui/"+uid+"/"+launchdLabel, serviceBootoutTimeout) { + return fmt.Errorf("the previous %s is still shutting down after %s; "+ + "run `abctl service status`, then try again", supervisorName(), serviceBootoutTimeout) + } + + // Retried on EIO: the wait above closes the window, and this closes the race + // inside it. Bootstrap is idempotent from our side — the label is not in the + // domain, or we would not be here. + var out []byte + var err error + 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) } // bootstrap REGISTERS the job; it does not reliably start it. Observed on a // real install: the agent loaded, `state = not running`, nothing served, and @@ -525,3 +552,21 @@ 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 { + deadline := time.Now().Add(d) + for { + if err := exec.Command("launchctl", "print", target).Run(); err != nil { + return true // no longer in the domain + } + if time.Now().After(deadline) { + return false + } + time.Sleep(250 * time.Millisecond) + } +} From 37dad68c3ccbb7c382c6f2f54b5169b670e15f20 Mon Sep 17 00:00:00 2001 From: Hai Huang Date: Fri, 4 Sep 2026 17:08:35 -0400 Subject: [PATCH 2/2] =?UTF-8?q?fix:=20Address=20review=20=E2=80=94=20pin?= =?UTF-8?q?=20the=20call=20site,=20and=20stop=20the=20wait=20looking=20lik?= =?UTF-8?q?e=20a=20hang?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Six findings, all valid. The first two are the same criticism I earned last round. **Nothing covered the call site.** Verified by mutation: deleting the waitBootedOut call from loadService left the whole suite green — the second time in this PR series that a test asserted a helper's content while the wiring that mattered went unpinned. TestBootoutWaitIsWiredIn now reads the source and requires bootout → wait → bootstrap in that order, using the idiom TestStopIsDurable already established, and it runs on Linux CI unlike the launchd test. Re-mutated with a form that still compiles: it fails. **The launchd test had four skip paths**, so it could report success having executed no assertion — on the 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. **Up to 30s of silent polling** sat immediately after "Setting up the launchd user agent...", indistinguishable from a hang, for exactly the people who just hit the EIO failure. A progress writer is plumbed through loadService and controlService; one line after the first second, so a fast teardown stays silent. Testing that needed a change: there is no way to hold a real launchd label half-torn-down on demand, so the first attempt could only skip. The polling is now injectable (waitGone takes the predicate), and the progress behaviour is covered deterministically — silent fast path, announce-then-confirm slow path, timeout, and a nil writer. **A refused bootout was reported as "still shutting down".** Wrong cause, and it told the user to try again when retrying cannot help. bootout's output is now kept and consulted only if the label is still present, so "could not remove" and "still shutting down" are distinguishable. Its error alone is not a signal — it also fails when nothing was loaded, the common case. **The retry comment was only true for the first attempt.** An attempt that registers the label and then fails leaves the next returning "File exists" rather than EIO. Each retry now re-checks the domain, making the claim true as written. **Dropped the unnecessary var hoisting** in the bootstrap loop. One thing the review's own suggestion cost: refactoring to a `target` variable broke TestStopIsDurable, which matched the exact former literal. That is the standing price of reading source instead of driving code — the assertion is looser now, and says so. Assisted-By: Claude (Anthropic AI) Signed-off-by: Hai Huang --- authbridge/cmd/abctl/cmd_service.go | 4 +- .../cmd/abctl/cmd_service_bootout_test.go | 102 +++++++++++++++++- .../cmd/abctl/cmd_service_durable_test.go | 6 +- authbridge/cmd/abctl/cmd_service_platform.go | 81 ++++++++++---- 4 files changed, 167 insertions(+), 26 deletions(-) diff --git a/authbridge/cmd/abctl/cmd_service.go b/authbridge/cmd/abctl/cmd_service.go index 70512e73..304c84f5 100644 --- a/authbridge/cmd/abctl/cmd_service.go +++ b/authbridge/cmd/abctl/cmd_service.go @@ -338,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) @@ -499,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 index daa7ca6d..96556326 100644 --- a/authbridge/cmd/abctl/cmd_service_bootout_test.go +++ b/authbridge/cmd/abctl/cmd_service_bootout_test.go @@ -1,6 +1,7 @@ package main import ( + "bytes" "os" "os/exec" "path/filepath" @@ -18,12 +19,55 @@ import ( // 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" { - t.Skip("launchd only") + skip("launchd only (GOOS=%s)", runtime.GOOS) + return } if _, err := exec.LookPath("launchctl"); err != nil { - t.Skip("no launchctl") + skip("no launchctl: %v", err) + return } uid := strconv.Itoa(os.Getuid()) label := "io.rossoctl.cortex.test.bootout" @@ -55,7 +99,8 @@ func TestWaitBootedOut_RealLaunchd(t *testing.T) { _ = 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 { - t.Skipf("cannot bootstrap a test agent here: %v: %s", err, out) + skip("cannot bootstrap a test agent here: %v: %s", err, out) + return } _ = exec.Command("launchctl", "kickstart", "-p", target).Run() //nolint:errcheck @@ -77,7 +122,8 @@ func TestWaitBootedOut_RealLaunchd(t *testing.T) { time.Sleep(200 * time.Millisecond) } if !running { - t.Skip("launchd would not start the test agent in this domain; cannot exercise the race") + 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. @@ -103,3 +149,51 @@ func TestWaitBootedOut_RealLaunchd(t *testing.T) { 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 904df743..f8422dcf 100644 --- a/authbridge/cmd/abctl/cmd_service_platform.go +++ b/authbridge/cmd/abctl/cmd_service_platform.go @@ -146,16 +146,21 @@ 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 + _ = 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 @@ -167,18 +172,21 @@ func loadService(p servicePaths) error { // 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 !waitBootedOut("gui/"+uid+"/"+launchdLabel, serviceBootoutTimeout) { + 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: the wait above closes the window, and this closes the race - // inside it. Bootstrap is idempotent from our side — the label is not in the - // domain, or we would not be here. - var out []byte - var err error + // 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() + out, err := exec.Command("launchctl", "bootstrap", "gui/"+uid, p.unitFile).CombinedOutput() if err == nil { break } @@ -186,6 +194,10 @@ func loadService(p servicePaths) 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 @@ -366,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 { @@ -389,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 { @@ -559,12 +571,43 @@ func unitWriterVersion(unitFile string) string { // 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 { - deadline := time.Now().Add(d) + 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 err := exec.Command("launchctl", "print", target).Run(); err != nil { - return true // no longer in the domain + 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.Now().After(deadline) { + if time.Since(start) > d { return false } time.Sleep(250 * time.Millisecond)