From a66563304ea5dc99958a926348f8ec8f83cda593 Mon Sep 17 00:00:00 2001 From: Teo Calin Date: Thu, 1 Oct 2026 18:25:49 +0300 Subject: [PATCH 1/3] appstore: install waits for the app's first start and reports it install only writes files; the daemon's supervisor starts the app on its next rescan. So install exited 0 for an app that then exited at every start (io.pilot.sqlite on an image without tar), and the app was suspended about half a minute later with nothing in the install output. With a daemon listening, install now watches the app dir (supervisor.log, .suspended, app.sock) for up to 20s after the swap and reports: - started: a spawn since the install and the socket is there; - failed: the supervisor suspended the app, or it exited at least twice with no socket (three times when an install was replaced, since the instance the supervisor stops logs an exit too). install prints its report and then exits non-zero (app_start_failed) with the last supervisor log line and pointers to `appstore audit` and the daemon log; - starting: neither by the deadline. Exit 0 with a note, so an app that takes longer than the wait to open its socket is not a failed install. Waiting for .suspended alone would not do: the supervisor suspends after more than 5 exits in a minute, 31s at the earliest. No wait with --no-wait, when no daemon is listening, or for a reinstall the supervisor does not act on (same version and binary, or an older version). `appstore upgrade` passes --no-wait: it would otherwise report a failed start as "was not upgraded", and the hourly `upgrade --all` would spend the wait on every app. The JSON report gains start_state, start_exits, start_detail and start_waited_ms; existing fields are unchanged. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 15 + cmd/pilotctl/appstore.go | 72 +++- cmd/pilotctl/appstore_startwait.go | 195 +++++++++ cmd/pilotctl/appstore_update.go | 6 +- .../zz_appstore_startwait_supervisor_test.go | 101 +++++ cmd/pilotctl/zz_appstore_startwait_test.go | 405 ++++++++++++++++++ 6 files changed, 788 insertions(+), 6 deletions(-) create mode 100644 cmd/pilotctl/appstore_startwait.go create mode 100644 cmd/pilotctl/zz_appstore_startwait_supervisor_test.go create mode 100644 cmd/pilotctl/zz_appstore_startwait_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 4205fb00..50d12e21 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -291,6 +291,21 @@ Detailed per-release notes are on the new binary. In every other case the daemon keeps running and `restart_error` says how to restart it. Every check is recorded in `~/.pilot/update-state.json`. +- **`pilotctl appstore install` says whether the app started.** Install only + writes files and the daemon starts the app a moment later, so it reported + success for an app that then exited at every start (seen with + `io.pilot.sqlite` on an image without `tar`) and was suspended half a minute + later. With a daemon running, install now waits up to 20s for the first + start and reports one of three outcomes: started; failed — the supervisor + suspended the app, or it exited at least twice without opening its socket — + in which case install **exits non-zero** (`app_start_failed`) with the last + supervisor log line and where to look next; or still starting, which is not + an error, so an app that needs longer than the wait is not a failed + install. The `--json` report gains `start_state`, `start_exits`, + `start_detail` and `start_waited_ms`; nothing existing changed. No wait + with `--no-wait`, when no daemon is running, or for a reinstall the + supervisor does not act on (same version and binary, or an older version). + `appstore upgrade` does not wait. ### Fixed - **Stream segments fit one packet.** A full stream segment was 4096 bytes, diff --git a/cmd/pilotctl/appstore.go b/cmd/pilotctl/appstore.go index 2e93bb95..15815a70 100644 --- a/cmd/pilotctl/appstore.go +++ b/cmd/pilotctl/appstore.go @@ -126,7 +126,11 @@ Usage: (another --version needs --force: conflict otherwise). --force reinstalls in place and KEEPS the app's state (keys, data.db, secrets, cap-state, audit log); - --reset-state (implies --force) starts it empty + --reset-state (implies --force) starts it empty. + with a daemon running, waits up to 20s for the app's + first start and exits non-zero if it crashed at start + or was suspended; an app still starting by then is + not an error. --no-wait returns at once pilotctl appstore install --local [--force [--reset-state]] sideload a local bundle (sandbox: fs.read/fs.write under $APP, audit.log; no net, no key.sign, no hooks) @@ -1082,6 +1086,18 @@ type installReport struct { StateNotCarried []string `json:"state_not_carried,omitempty"` // BackupDir is where the replaced install was kept. BackupDir string `json:"backup_dir,omitempty"` + // StartState is what install saw of the app's first start, when it + // waited for it: "started", "failed" (install then exits non-zero) or + // "starting" (not ready by the end of the wait; not a failure). Absent + // when install did not wait: --no-wait, no daemon running, or a + // reinstall the supervisor does not act on. + StartState string `json:"start_state,omitempty"` + // StartExits counts the app's exits seen during the wait, StartDetail is + // the last supervisor.log line of the wait, StartWaitedMs how long + // install waited. + StartExits int `json:"start_exits,omitempty"` + StartDetail string `json:"start_detail,omitempty"` + StartWaitedMs int64 `json:"start_waited_ms,omitempty"` // BackupWarning is set when the backup is not where it was configured // to go (or could not be completed); the same text goes to stderr. BackupWarning string `json:"backup_warning,omitempty"` @@ -1146,7 +1162,7 @@ func resolveAppDir(root, appID string) (string, error) { func cmdAppStoreInstall(args []string) { if len(args) < 1 { fatalHint("invalid_argument", - "usage: pilotctl appstore install [--force [--reset-state]] [--local] [--version ]", + "usage: pilotctl appstore install [--force [--reset-state]] [--local] [--version ] [--no-wait]", "missing app id or bundle dir") } target := args[0] @@ -1154,6 +1170,7 @@ func cmdAppStoreInstall(args []string) { resetState := false wantVersion := "" allowLocal := false + noWait := false for i := 1; i < len(args); i++ { switch args[i] { case "--force", "-f": @@ -1179,9 +1196,13 @@ func cmdAppStoreInstall(args []string) { // happens to also exist as a directory in the cwd) can't // silently sideload an unsigned bundle. allowLocal = true + case "--no-wait": + // Return as soon as the files are in place, without waiting to + // see the daemon start the app (appstore_startwait.go). + noWait = true default: fatalHint("invalid_argument", - "available flags: --force, --reset-state, --local, --version", + "available flags: --force, --reset-state, --local, --version, --no-wait", "unknown install flag: %s", args[i]) } } @@ -1515,6 +1536,8 @@ func cmdAppStoreInstall(args []string) { if testHookBeforeSwap != nil { testHookBeforeSwap(finalDir) } + // Supervisor events older than this belong to the install being replaced. + swapAt := time.Now() // 4. Swap. The live dir is renamed to .previous and kept there // until the new dir verifies (exact manifest, pinned binary sha, // carried state); on any failure the previous install is restored. @@ -1646,6 +1669,22 @@ func cmdAppStoreInstall(args []string) { } } + // Wait for the daemon to start the app and see how that went + // (appstore_startwait.go). Not when nothing will start it: no daemon, or + // a reinstall the supervisor does not act on (same version and binary, + // which it leaves running, or an older version, which it refuses). + var start *appStartStatus + supervisorActs := oldManifest == nil || + (semverCompare(m.AppVersion, oldManifest.AppVersion) >= 0 && + (m.AppVersion != oldManifest.AppVersion || m.Binary.SHA256 != oldManifest.Binary.SHA256)) + if !noWait && supervisorActs && daemonSocketReachable() { + if !jsonOutput { + fmt.Fprintf(os.Stderr, "installed %s v%s; waiting up to %s for the daemon to start it (--no-wait skips this)...\n", m.ID, m.AppVersion, appStartWait) + } + st := waitForAppStart(finalDir, swapAt, replacing, appStartWait) + start = &st + } + report := installReport{ AppID: m.ID, AppVersion: m.AppVersion, @@ -1659,8 +1698,25 @@ func cmdAppStoreInstall(args []string) { BackupDir: backupDir, BackupWarning: backupWarning, } + if start != nil { + report.StartState = start.State + report.StartExits = start.Exits + report.StartDetail = start.LastEvent + report.StartWaitedMs = start.Waited.Milliseconds() + } + // failIfNotStarted ends the command non-zero when the app was seen + // failing to start. The files are installed either way, so the report + // above is printed first. + failIfNotStarted := func() { + if start == nil || start.State != appStartFailed { + return + } + what, hint := start.startFailure(m.ID) + fatalHint("app_start_failed", hint, "%s v%s is installed in %s but did not start: %s", m.ID, m.AppVersion, finalDir, what) + } if jsonOutput { _ = json.NewEncoder(os.Stdout).Encode(report) + failIfNotStarted() return } fmt.Printf("installed %s v%s (manifest v%d) → %s\n", @@ -1681,8 +1737,14 @@ func cmdAppStoreInstall(args []string) { fmt.Println(" this is NOT an OS sandbox: a malicious binary that ignores its manifest can still") fmt.Println(" misbehave at the syscall level. Only install paths from sources you trust.") } - fmt.Println("note: the daemon rescans the install root periodically —") - fmt.Println(" this app will be picked up within ~30s (no daemon restart needed)") + failIfNotStarted() + if start != nil { + fmt.Println(start.startNote(m.ID)) + } + if start == nil || !start.Picked { + fmt.Println("note: the daemon rescans the install root periodically —") + fmt.Println(" this app will be picked up within ~30s (no daemon restart needed)") + } // Last step: if this catalogue app ships a product demo in its // sha-verified metadata, print it and drop a SKILL.md so the agent can diff --git a/cmd/pilotctl/appstore_startwait.go b/cmd/pilotctl/appstore_startwait.go new file mode 100644 index 00000000..1b4213f6 --- /dev/null +++ b/cmd/pilotctl/appstore_startwait.go @@ -0,0 +1,195 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "bufio" + "encoding/json" + "fmt" + "net" + "os" + "path/filepath" + "strings" + "time" +) + +// Did the app start? (`appstore install`) +// +// install only writes files; the daemon's supervisor starts the app on its +// next rescan (2s). So install used to report success for an app that then +// exited at every start: on an image without tar, io.pilot.sqlite's adapter +// failed while staging its assets, was restarted five times and suspended, +// and the install output said nothing. +// +// After a successful install, with a daemon to start the app, install now +// watches the app dir for up to appStartWait and reports one of: +// +// - started: the supervisor spawned the app and its socket is there. +// - failed: the supervisor suspended it, or it exited at least twice +// without its socket being there. install exits non-zero. +// - starting: neither, by the deadline. Not a failure: an app that takes +// longer than the wait to open its socket is healthy. +// +// Everything is read from the app dir (supervisor.log, .suspended, +// app.sock), like `list` and `status` do: pilotctl has no channel to the +// supervisor. The supervisor only suspends an app after more than five exits +// in a minute, 31s at the earliest, so waiting for .suspended alone would +// either miss the failure or cost every install half a minute; two exits are +// there after about 3s. + +// appStartWait bounds how long install waits for the app's first start. +// appStartPoll is how often it looks. Vars so tests can shorten them. +var ( + appStartWait = 20 * time.Second + appStartPoll = 200 * time.Millisecond +) + +const ( + appStartStarted = "started" + appStartFailed = "failed" + appStartStarting = "starting" +) + +// appStartExitsForFailure is how many exits without a socket make a failed +// start. One could be anything; a second, after the supervisor's 1s restart +// delay, means the app does not come up on its own. +const appStartExitsForFailure = 2 + +// appStartStatus is what install saw of the app's first start. +type appStartStatus struct { + State string // appStartStarted, appStartFailed or appStartStarting + Waited time.Duration + Picked bool // the supervisor has logged something for this install + Spawns int // spawn events since the install + Exits int // exit events since the install + ExitCode int // exit code of the last of them + Suspended bool // the supervisor gave up on the app + LastEvent string // last supervisor.log line since the install, as written +} + +// supervisorEvent is the part of a supervisor.log line install looks at. +type supervisorEvent struct { + At time.Time `json:"at"` + Event string `json:"event"` + ExitCode int `json:"exit_code"` + Reason string `json:"reason"` +} + +// readAppStart reads the app dir once. since is when the new install was +// swapped in: older log lines belong to a previous install, whose log is +// carried over. replaced is true when an install was replaced: the instance +// the supervisor stops for it logs one exit of its own. +func readAppStart(appDir string, since time.Time, replaced bool) appStartStatus { + var st appStartStatus + if f, err := os.Open(filepath.Join(appDir, "supervisor.log")); err == nil { // #nosec G304 -- //supervisor.log + sc := bufio.NewScanner(f) + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for sc.Scan() { + line := strings.TrimSpace(sc.Text()) + var ev supervisorEvent + if line == "" || json.Unmarshal([]byte(line), &ev) != nil || ev.At.Before(since) { + continue + } + if ev.Event == "installed" { + continue // written by pilotctl itself + } + st.Picked = true + st.LastEvent = line + switch ev.Event { + case "spawn": + st.Spawns++ + case "exit": + st.Exits++ + st.ExitCode = ev.ExitCode + case "suspend": + st.Suspended = true + case "resume": + st.Suspended = false + } + } + _ = f.Close() + } + // The marker of a previous install can be carried into this one before + // the supervisor clears it, so only one written since the swap counts. + if fi, err := os.Stat(filepath.Join(appDir, ".suspended")); err == nil && !fi.ModTime().Before(since) { + st.Suspended = true + } + _, sockErr := os.Stat(filepath.Join(appDir, "app.sock")) + needExits := appStartExitsForFailure + if replaced { + needExits++ + } + switch { + case st.Suspended: + st.State = appStartFailed + case sockErr == nil && st.Spawns > 0: + st.State = appStartStarted + case sockErr != nil && st.Exits >= needExits: + st.State = appStartFailed + default: + st.State = appStartStarting + } + return st +} + +// waitForAppStart polls the app dir until the start is decided either way, +// or wait has passed. +func waitForAppStart(appDir string, since time.Time, replaced bool, wait time.Duration) appStartStatus { + begin := time.Now() + for { + st := readAppStart(appDir, since, replaced) + st.Waited = time.Since(begin) + if st.State != appStartStarting || st.Waited >= wait { + return st + } + time.Sleep(appStartPoll) + } +} + +// daemonSocketReachable reports whether a daemon is listening on the control +// socket. Without one nothing starts the app, and there is nothing to wait +// for. +func daemonSocketReachable() bool { + c, err := net.DialTimeout("unix", getSocket(), 500*time.Millisecond) + if err != nil { + return false + } + _ = c.Close() + return true +} + +// startFailure words a failed start: what happened, and where to look. +func (st appStartStatus) startFailure(appID string) (what, hint string) { + if st.Suspended { + what = "the daemon suspended it after repeated crashes" + } else { + what = fmt.Sprintf("it exited %d times at start (last exit code %d)", st.Exits, st.ExitCode) + } + hint = "the files are installed, the app is not running. " + if st.LastEvent != "" { + hint += "Last supervisor event: " + st.LastEvent + ". " + } + hint += "`pilotctl appstore audit " + appID + "` shows the supervisor's events; the app's own error output is in the daemon's log. " + if st.Suspended { + hint += "After fixing the cause: `pilotctl appstore restart " + appID + "`." + } else { + hint += "The daemon keeps restarting it and suspends it after more than 5 exits in a minute; once it is suspended, `pilotctl appstore restart " + appID + "` retries it." + } + hint += " To remove it: `pilotctl appstore uninstall " + appID + " --yes`." + return what, hint +} + +// startNote is the one line install prints for a start that did not fail. +func (st appStartStatus) startNote(appID string) string { + waited := st.Waited.Round(100 * time.Millisecond) + switch { + case st.State == appStartStarted: + return fmt.Sprintf("started: the daemon is running %s (socket ready after %s)", appID, waited) + case !st.Picked: + return fmt.Sprintf("note: the daemon has not started %s after %s; it picks new apps up on its rescan. Check with `pilotctl appstore status %s`", appID, waited, appID) + case st.Exits > 0: + return fmt.Sprintf("note: %s is not ready after %s and has exited %d time(s) (last exit code %d); the daemon is restarting it. Check with `pilotctl appstore status %s` and `pilotctl appstore audit %s`", appID, waited, st.Exits, st.ExitCode, appID, appID) + default: + return fmt.Sprintf("note: %s is still starting after %s (no socket yet); check with `pilotctl appstore status %s`", appID, waited, appID) + } +} diff --git a/cmd/pilotctl/appstore_update.go b/cmd/pilotctl/appstore_update.go index db97bc9d..53623fde 100644 --- a/cmd/pilotctl/appstore_update.go +++ b/cmd/pilotctl/appstore_update.go @@ -279,7 +279,11 @@ func cmdAppStoreUpgrade(args []string) { // state (keys, data.db, secrets, cap-state, audit log) is carried into // the new install and the replaced dir is kept as a backup — see // appstore_state.go. This is the path the hourly updater drives. - install := func() { cmdAppStoreInstall([]string{o.ID, "--force"}) } + // --no-wait: upgrade does not watch the app start. A failed start + // would be reported as "was not upgraded and stays at ", which + // is not what happened, and the hourly `upgrade --all` would spend + // the wait on every app. + install := func() { cmdAppStoreInstall([]string{o.ID, "--force", "--no-wait"}) } if len(targets) == 1 { install() continue diff --git a/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go b/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go new file mode 100644 index 00000000..a3026e16 --- /dev/null +++ b/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go @@ -0,0 +1,101 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "context" + "encoding/json" + "io" + "log" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/pilot-protocol/app-store/plugin/appstore" +) + +// installUnderRealSupervisor installs a local bundle whose binary is the +// given shell script while the daemon's real app supervisor (the app-store +// module, with the daemon's 2s rescan shortened) watches the install root. +// Unlike the tests in zz_appstore_startwait_test.go, nothing here writes +// supervisor.log by hand: what install reads is what the supervisor wrote. +func installUnderRealSupervisor(t *testing.T, id, script string) (report map[string]any, stderr string, failure *trappedFatal) { + t.Helper() + root := isolateAppStoreTest(t) + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + + svc := appstore.NewService(appstore.Config{ + InstallRoot: root, + RescanInterval: 100 * time.Millisecond, + Logger: log.New(io.Discard, "", 0), + }) + ctx, cancel := context.WithCancel(context.Background()) + if err := svc.Start(ctx, appstore.Deps{}); err != nil { + cancel() + t.Fatalf("start supervisor: %v", err) + } + t.Cleanup(func() { + cancel() + // The healthy test app runs for as long as its socket file exists. + _ = os.Remove(filepath.Join(root, id, "app.sock")) + stopCtx, stopCancel := context.WithTimeout(context.Background(), 20*time.Second) + defer stopCancel() + _ = svc.Stop(stopCtx) + }) + + // writeVersionedBundle writes "#!/bin/sh\necho \n". The supervisor + // runs in this process and hands the app this process's stderr, which is + // the pipe runTrapped captures while the install runs; the app lets go of + // it at once, or the capture would wait for the app to exit. + bundle := writeVersionedBundle(t, id, "1.0.0", "starting >/dev/null\nexec >/dev/null 2>&1\n"+script) + var stdout string + withJSON(func() { + stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local"}) }) + }) + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("install report: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) + } + log, _ := os.ReadFile(filepath.Join(root, id, "supervisor.log")) + t.Logf("supervisor.log:\n%s", log) + return report, stderr, failure +} + +func TestAppStoreInstallUnderRealSupervisorCrashingApp(t *testing.T) { + if testing.Short() { + t.Skip("waits out the supervisor's 1s restart delay") + } + const id = "io.test.realcrash" + report, stderr, f := installUnderRealSupervisor(t, id, "exit 7") + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("install = %+v, want app_start_failed\nreport: %v\nstderr: %s", f, report, stderr) + } + if !strings.Contains(f.Message, "exited 2 times at start (last exit code 7)") { + t.Errorf("message = %q", f.Message) + } + if report["start_state"] != appStartFailed { + t.Errorf("report = %v", report) + } + if ms, _ := report["start_waited_ms"].(float64); ms > 15000 { + t.Errorf("took %vms to see two exits", ms) + } +} + +func TestAppStoreInstallUnderRealSupervisorHealthyApp(t *testing.T) { + if testing.Short() { + t.Skip("starts a real process") + } + // Opens its "socket" (the supervisor and pilotctl only look for the + // path) and keeps running, like an app does, until the file is removed. + script := `while [ $# -gt 0 ]; do if [ "$1" = "--socket" ]; then sock="$2"; fi; shift; done +: > "$sock" +while [ -e "$sock" ]; do sleep 0.2; done` + report, stderr, f := installUnderRealSupervisor(t, "io.test.realhealthy", script) + if f != nil { + t.Fatalf("install of a healthy app failed: %+v\n%s", f, stderr) + } + if report["start_state"] != appStartStarted { + t.Fatalf("report = %v", report) + } +} diff --git a/cmd/pilotctl/zz_appstore_startwait_test.go b/cmd/pilotctl/zz_appstore_startwait_test.go new file mode 100644 index 00000000..4c1220f9 --- /dev/null +++ b/cmd/pilotctl/zz_appstore_startwait_test.go @@ -0,0 +1,405 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +// supLog appends supervisor.log lines the way the daemon's supervisor writes +// them. +func supLog(t *testing.T, appDir string, at time.Time, events ...string) { + t.Helper() + f, err := os.OpenFile(filepath.Join(appDir, "supervisor.log"), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) + if err != nil { + t.Fatal(err) + } + defer f.Close() + for _, ev := range events { + name, extra, _ := strings.Cut(ev, " ") + line := fmt.Sprintf(`{"at":%q,"app":"io.test.app","event":%q`, at.UTC().Format(time.RFC3339Nano), name) + if extra != "" { + line += "," + extra + } + if _, err := f.WriteString(line + "}\n"); err != nil { + t.Fatal(err) + } + } +} + +func touch(t *testing.T, path string) { + t.Helper() + if err := os.WriteFile(path, nil, 0o600); err != nil { + t.Fatal(err) + } +} + +func TestReadAppStart(t *testing.T) { + since := time.Now().Add(-time.Minute) + before, after := since.Add(-time.Hour), since.Add(time.Second) + const exit1 = `exit "exit_code":1` + + for _, tc := range []struct { + name string + replaced bool + setup func(t *testing.T, dir string) + want string + check func(t *testing.T, st appStartStatus) + }{ + {name: "nothing yet", setup: func(*testing.T, string) {}, want: appStartStarting, + check: func(t *testing.T, st appStartStatus) { + if st.Picked { + t.Error("Picked with no supervisor event") + } + }}, + {name: "only pilotctl's own install line", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "installed") + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Picked || st.LastEvent != "" { + t.Errorf("pilotctl's install line counted as a supervisor event: %+v", st) + } + }}, + {name: "spawned, socket not there yet", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", "spawn") + }, want: appStartStarting}, + {name: "spawned and socket there", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", "spawn") + touch(t, filepath.Join(dir, "app.sock")) + }, want: appStartStarted}, + {name: "socket without a spawn since the install is a leftover", setup: func(t *testing.T, dir string) { + supLog(t, dir, before, "supervise-start", "spawn") + touch(t, filepath.Join(dir, "app.sock")) + }, want: appStartStarting}, + {name: "one exit is not a failure", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", "spawn", exit1) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 1 || st.ExitCode != 1 { + t.Errorf("exits=%d code=%d", st.Exits, st.ExitCode) + } + }}, + {name: "two exits and no socket", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", "spawn", exit1, "spawn", `exit "exit_code":3`) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 2 || st.ExitCode != 3 || !strings.Contains(st.LastEvent, `"exit_code":3`) { + t.Errorf("%+v", st) + } + }}, + {name: "exited once, then came up", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", "spawn", exit1, "spawn") + touch(t, filepath.Join(dir, "app.sock")) + }, want: appStartStarted}, + {name: "exits of the previous install do not count", setup: func(t *testing.T, dir string) { + supLog(t, dir, before, "spawn", exit1, "spawn", exit1, "spawn", exit1, "suspend") + supLog(t, dir, after, "supervise-start", "spawn") + }, want: appStartStarting}, + {name: "replaced install: the stopped old instance logs an exit too", replaced: true, setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "upgrade-applied", "exit", "supervise-start", "spawn", exit1) + }, want: appStartStarting}, + {name: "replaced install: three exits", replaced: true, setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "upgrade-applied", "exit", "supervise-start", "spawn", exit1, "spawn", exit1) + }, want: appStartFailed}, + {name: "suspend event", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, "supervise-start", `verify-fail "reason":"sha256 mismatch"`, `suspend "reason":">=10 consecutive verify failures"`) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if !st.Suspended { + t.Error("not marked suspended") + } + }}, + {name: "suspended marker written since the install", setup: func(t *testing.T, dir string) { + touch(t, filepath.Join(dir, ".suspended")) + }, want: appStartFailed}, + {name: "suspended marker carried from the previous install", setup: func(t *testing.T, dir string) { + marker := filepath.Join(dir, ".suspended") + touch(t, marker) + if err := os.Chtimes(marker, before, before); err != nil { + t.Fatal(err) + } + }, want: appStartStarting}, + } { + t.Run(tc.name, func(t *testing.T) { + dir := t.TempDir() + tc.setup(t, dir) + st := readAppStart(dir, since, tc.replaced) + if st.State != tc.want { + t.Fatalf("state = %q, want %q (%+v)", st.State, tc.want, st) + } + if tc.check != nil { + tc.check(t, st) + } + }) + } +} + +func shortStartWait(t *testing.T, wait time.Duration) { + t.Helper() + prevWait, prevPoll := appStartWait, appStartPoll + appStartWait, appStartPoll = wait, 20*time.Millisecond + t.Cleanup(func() { appStartWait, appStartPoll = prevWait, prevPoll }) +} + +// The wait ends as soon as the start is decided, and at the deadline +// otherwise: an app that is merely slow is "starting", never "failed". +func TestWaitForAppStart(t *testing.T) { + shortStartWait(t, 0) + t.Run("returns when the socket appears", func(t *testing.T) { + dir := t.TempDir() + since := time.Now() + go func() { + time.Sleep(200 * time.Millisecond) + supLog(t, dir, time.Now(), "supervise-start", "spawn") + touch(t, filepath.Join(dir, "app.sock")) + }() + st := waitForAppStart(dir, since, false, 10*time.Second) + if st.State != appStartStarted || st.Waited > 5*time.Second { + t.Fatalf("%+v", st) + } + }) + t.Run("returns on the second exit", func(t *testing.T) { + dir := t.TempDir() + since := time.Now() + go func() { + time.Sleep(100 * time.Millisecond) + supLog(t, dir, time.Now(), "supervise-start", "spawn", `exit "exit_code":1`) + time.Sleep(100 * time.Millisecond) + supLog(t, dir, time.Now(), "spawn", `exit "exit_code":1`) + }() + st := waitForAppStart(dir, since, false, 10*time.Second) + if st.State != appStartFailed || st.Waited > 5*time.Second { + t.Fatalf("%+v", st) + } + }) + t.Run("a slow app is still starting at the deadline", func(t *testing.T) { + dir := t.TempDir() + supLog(t, dir, time.Now(), "supervise-start", "spawn") + st := waitForAppStart(dir, time.Now().Add(-time.Second), false, 300*time.Millisecond) + if st.State != appStartStarting || st.Waited < 300*time.Millisecond { + t.Fatalf("%+v", st) + } + }) +} + +// installWithSupervisor installs a local bundle with a daemon socket +// listening, while supervise plays the daemon's supervisor on the app dir +// once the install has put the manifest there. +func installWithSupervisor(t *testing.T, id string, supervise func(appDir string), args ...string) (root string, report map[string]any, stderr string, failure *trappedFatal) { + t.Helper() + root = isolateAppStoreTest(t) + sd := newStreamDaemon(t) + t.Setenv("PILOT_SOCKET", sd.path) + appDir := filepath.Join(root, id) + done := make(chan struct{}) + stop := make(chan struct{}) + go func() { + defer close(done) + for { + if _, err := os.Stat(filepath.Join(appDir, "manifest.json")); err == nil { + break + } + select { + case <-stop: + return + case <-time.After(10 * time.Millisecond): + } + } + if supervise != nil { + supervise(appDir) + } + }() + bundle := writeVersionedBundle(t, id, "1.0.0", "v1") + var stdout string + withJSON(func() { + stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall(append([]string{bundle, "--local"}, args...)) }) + }) + close(stop) + <-done + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("install report: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) + } + return root, report, stderr, failure +} + +func TestAppStoreInstallReportsStartedApp(t *testing.T) { + shortStartWait(t, 10*time.Second) + const id = "io.test.starts" + _, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { + time.Sleep(150 * time.Millisecond) // the rescan + supLog(t, appDir, time.Now(), "supervise-start", "spawn") + touch(t, filepath.Join(appDir, "app.sock")) + }) + if f != nil { + t.Fatalf("install failed: %+v\n%s", f, stderr) + } + if report["start_state"] != appStartStarted || report["id"] != id { + t.Fatalf("report = %v", report) + } +} + +// The lab case: the app exits at every start. install used to exit 0 and +// say nothing. +func TestAppStoreInstallFailsForAppThatCrashesAtStart(t *testing.T) { + shortStartWait(t, 10*time.Second) + const id = "io.test.crashes" + root, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { + supLog(t, appDir, time.Now(), "supervise-start", "spawn", `exit "exit_code":1`) + time.Sleep(100 * time.Millisecond) // the supervisor's restart delay + supLog(t, appDir, time.Now(), "spawn", `exit "exit_code":1`) + }) + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("install = %+v, want app_start_failed\nstderr: %s", f, stderr) + } + if !strings.Contains(f.Message, "exited 2 times at start (last exit code 1)") { + t.Errorf("message = %q", f.Message) + } + // (stderr is the JSON error document, so the quoted log line is escaped.) + for _, part := range []string{"Last supervisor event", "exit_code", "pilotctl appstore audit " + id, "daemon's log", "pilotctl appstore uninstall " + id} { + if !strings.Contains(stderr, part) { + t.Errorf("error output does not mention %q:\n%s", part, stderr) + } + } + // The report is still printed, and the files are installed. + if report["start_state"] != appStartFailed || report["start_exits"] != float64(2) || !strings.Contains(fmt.Sprint(report["start_detail"]), `"exit_code":1`) { + t.Errorf("report = %v", report) + } + if _, err := os.Stat(filepath.Join(root, id, "manifest.json")); err != nil { + t.Errorf("the app is not installed: %v", err) + } +} + +func TestAppStoreInstallFailsForSuspendedApp(t *testing.T) { + shortStartWait(t, 10*time.Second) + const id = "io.test.suspended" + _, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { + supLog(t, appDir, time.Now(), "supervise-start", `suspend "reason":">5 crashes in 1m0s"`) + touch(t, filepath.Join(appDir, ".suspended")) + }) + if f == nil || f.Code != "app_start_failed" || !strings.Contains(f.Message, "suspended it after repeated crashes") { + t.Fatalf("install = %+v\nstderr: %s", f, stderr) + } + if !strings.Contains(stderr, "pilotctl appstore restart "+id) || report["start_state"] != appStartFailed { + t.Errorf("report = %v\nstderr: %s", report, stderr) + } +} + +// A healthy app that needs longer than the wait (mysql took 16s to be +// ready) is a successful install. +func TestAppStoreInstallSlowAppIsNotAFailure(t *testing.T) { + shortStartWait(t, 400*time.Millisecond) + _, report, stderr, f := installWithSupervisor(t, "io.test.slow", func(appDir string) { + supLog(t, appDir, time.Now(), "supervise-start", "spawn") + }) + if f != nil { + t.Fatalf("install of a slow app failed: %+v\n%s", f, stderr) + } + if report["start_state"] != appStartStarting { + t.Fatalf("report = %v", report) + } + if ms, _ := report["start_waited_ms"].(float64); ms < 400 || ms > 5000 { + t.Errorf("waited %vms for a 400ms wait", report["start_waited_ms"]) + } +} + +// No wait, and no start_state in the report, when it would be pointless. +func TestAppStoreInstallDoesNotWaitWhenNothingWillStartTheApp(t *testing.T) { + shortStartWait(t, 30*time.Second) // any wait would be obvious + fast := func(t *testing.T, report map[string]any, took time.Duration) { + t.Helper() + if _, has := report["start_state"]; has || took > 10*time.Second { + t.Fatalf("install waited (%s): %v", took, report) + } + } + t.Run("--no-wait", func(t *testing.T) { + begin := time.Now() + _, report, stderr, f := installWithSupervisor(t, "io.test.nowait", nil, "--no-wait") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + fast(t, report, time.Since(begin)) + }) + t.Run("no daemon", func(t *testing.T) { + isolateAppStoreTest(t) // points PILOT_SOCKET at a path nothing listens on + bundle := writeVersionedBundle(t, "io.test.nodaemon", "1.0.0", "v1") + begin := time.Now() + var stdout string + withJSON(func() { stdout, _ = installQuiet(t, bundle, "--local") }) + var report map[string]any + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("%v\n%s", err, stdout) + } + fast(t, report, time.Since(begin)) + }) + t.Run("reinstall of the same version and binary", func(t *testing.T) { + const id = "io.test.samebinary" + _, _, stderr, f := installWithSupervisor(t, id, nil, "--no-wait") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + // Same bundle again, with --force and without --no-wait: the + // supervisor leaves the running app alone, so there is no start to see. + // (The fake daemon serves one connection; give this install its own.) + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + bundle := writeVersionedBundle(t, id, "1.0.0", "v1") + begin := time.Now() + var stdout string + withJSON(func() { stdout, _ = installQuiet(t, bundle, "--local", "--force") }) + var report map[string]any + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("%v\n%s", err, stdout) + } + fast(t, report, time.Since(begin)) + }) +} + +// Human output: the start is reported in place of "will be picked up within +// ~30s", and a failed start still prints what was installed first. +func TestAppStoreInstallTextOutputReportsStart(t *testing.T) { + shortStartWait(t, 10*time.Second) + run := func(t *testing.T, id string, events ...string) (stdout, stderr string, f *trappedFatal) { + root := isolateAppStoreTest(t) + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + appDir := filepath.Join(root, id) + go func() { + for i := 0; i < 500; i++ { + if _, err := os.Stat(filepath.Join(appDir, "manifest.json")); err == nil { + supLog(t, appDir, time.Now(), events...) + if events[len(events)-1] == "spawn" { + touch(t, filepath.Join(appDir, "app.sock")) + } + return + } + time.Sleep(10 * time.Millisecond) + } + }() + bundle := writeVersionedBundle(t, id, "1.0.0", "v1") + return runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local"}) }) + } + t.Run("started", func(t *testing.T) { + stdout, stderr, f := run(t, "io.test.textok", "supervise-start", "spawn") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + if !strings.Contains(stdout, "started: the daemon is running io.test.textok") || strings.Contains(stdout, "within ~30s") { + t.Errorf("stdout:\n%s", stdout) + } + if !strings.Contains(stderr, "waiting up to") || !strings.Contains(stderr, "--no-wait") { + t.Errorf("stderr:\n%s", stderr) + } + }) + t.Run("failed", func(t *testing.T) { + stdout, stderr, f := run(t, "io.test.textbad", "supervise-start", "spawn", `exit "exit_code":1`, "spawn", `exit "exit_code":1`) + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("%+v\n%s", f, stderr) + } + if !strings.Contains(stdout, "installed io.test.textbad v1.0.0") || strings.Contains(stdout, "started:") { + t.Errorf("stdout:\n%s", stdout) + } + if !strings.Contains(stderr, `Last supervisor event: {"at":`) || !strings.Contains(stderr, "pilotctl appstore audit io.test.textbad") { + t.Errorf("stderr:\n%s", stderr) + } + }) +} From 161960bdca62e2ccd3a3a275999d2cc212c8a29c Mon Sep 17 00:00:00 2001 From: Teo Calin Date: Wed, 7 Oct 2026 16:38:14 +0300 Subject: [PATCH 2/3] appstore: install start report counts only the new install's events Review fixes for the wait on the app's first start. The replaced instance's events no longer count. supervisor.log is carried into the new install and the supervisor keeps running the old instance until its next rescan, so lines after the swap can still be the old instance's: the end of its crash loop (exits, a suspend and its .suspended marker) made a good upgrade report failed and exit 1, and the exit it logs when the rescan stops it showed up as start_exits: 1 on a clean upgrade. Counting now starts at the new instance's supervise-start or spawn, recognised by the installed manifest's binary sha256 they carry; an exit counts only when it ends one of the new instance's start attempts, and a suspend only when it follows one of its exits. The .suspended marker is no longer read: it names no instance, and the log has the suspend first. A rotated supervisor.log.1 written during the wait is read too. Versions are ordered as the supervisor orders them (a release above its prereleases), not with semverCompare, which ignores prereleases: --force from 1.0.0 to 1.0.0-beta.1 waited 20s for a start the supervisor refuses. A downgrade-refused line for the installed version is now a final outcome: failed, with the supervisor's reason and how to get the version running. A downgrade that is not waited for says the daemon starts it only when it restarts, instead of "picked up within ~30s". After a spawn-fail the failure reason is reported, not the exit -1 that follows it. A wait that ends before the daemon picked the app up prints one note instead of two that contradict each other. --wait changes the 20s (0 is --no-wait). --no-wait and --wait are in the main help, the JSON command catalogue and docs/cli-reference.md. Tests: the three install tests in zz_appstore_cmds_test.go dialled the daemon at /tmp/pilot.sock and waited 20s each when one was running; they now use isolateAppStoreTest. The fake-supervisor helpers report with t.Error, since they run on goroutines. New tests cover the upgrade log sequences, the refusal and the prerelease order, with the fake and the real supervisor; all of them fail on the previous commit. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 26 +- cmd/pilotctl/appstore.go | 69 ++- cmd/pilotctl/appstore_startwait.go | 290 ++++++++--- cmd/pilotctl/main.go | 6 +- cmd/pilotctl/zz_appstore_cmds_test.go | 13 +- .../zz_appstore_startwait_supervisor_test.go | 185 ++++++- cmd/pilotctl/zz_appstore_startwait_test.go | 472 +++++++++++++++--- docs/cli-reference.md | 4 +- 8 files changed, 881 insertions(+), 184 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 50d12e21..5c4a0ebd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -295,16 +295,22 @@ Detailed per-release notes are on the writes files and the daemon starts the app a moment later, so it reported success for an app that then exited at every start (seen with `io.pilot.sqlite` on an image without `tar`) and was suspended half a minute - later. With a daemon running, install now waits up to 20s for the first - start and reports one of three outcomes: started; failed — the supervisor - suspended the app, or it exited at least twice without opening its socket — - in which case install **exits non-zero** (`app_start_failed`) with the last - supervisor log line and where to look next; or still starting, which is not - an error, so an app that needs longer than the wait is not a failed - install. The `--json` report gains `start_state`, `start_exits`, - `start_detail` and `start_waited_ms`; nothing existing changed. No wait - with `--no-wait`, when no daemon is running, or for a reinstall the - supervisor does not act on (same version and binary, or an older version). + later. With a daemon running, install now waits up to 20s (`--wait ` + changes that) for the first start and reports one of three outcomes: + started; failed — the supervisor suspended the app, it exited at least + twice without opening its socket, or the supervisor refused it as older + than the version it runs — in which case install **exits non-zero** + (`app_start_failed`) with the last supervisor log line and where to look + next; or still starting, which is not an error, so an app that needs longer + than the wait is not a failed install. On an upgrade, what the replaced + instance logs before the daemon swaps it out (the end of its crash loop, or + its exit when it is stopped) is not counted against the new version. The + `--json` report gains `start_state`, `start_exits`, `start_detail` and + `start_waited_ms`; nothing existing changed. No wait with `--no-wait`, when + no daemon is running, or for a reinstall the supervisor does not act on + (same version and binary, or an older version, ordered as the supervisor + orders them, so `1.0.0-beta.1` is older than `1.0.0`); for an older + version install says the daemon starts it only when the daemon restarts. `appstore upgrade` does not wait. ### Fixed diff --git a/cmd/pilotctl/appstore.go b/cmd/pilotctl/appstore.go index 15815a70..5531648b 100644 --- a/cmd/pilotctl/appstore.go +++ b/cmd/pilotctl/appstore.go @@ -120,18 +120,19 @@ Usage: pilotctl appstore uninstall --yes remove an installed app from the install root pilotctl appstore verify sha256-check a pre-install bundle against its manifest pilotctl appstore catalogue list apps available for one-command install - pilotctl appstore install [--version ] [--force [--reset-state]] + pilotctl appstore install [--version ] [--force [--reset-state]] [--no-wait | --wait ] install by catalogue ID (fetches + verifies + extracts). already installed: a no-op that points at upgrade (another --version needs --force: conflict otherwise). --force reinstalls in place and KEEPS the app's state (keys, data.db, secrets, cap-state, audit log); --reset-state (implies --force) starts it empty. - with a daemon running, waits up to 20s for the app's - first start and exits non-zero if it crashed at start - or was suspended; an app still starting by then is - not an error. --no-wait returns at once - pilotctl appstore install --local [--force [--reset-state]] + with a daemon running, waits up to 20s (--wait ) + for the app's first start and exits non-zero if it + crashed at start, was suspended, or was refused as + older than the version the daemon runs; an app still + starting by then is not an error. --no-wait returns at once + pilotctl appstore install --local [--force [--reset-state]] [--no-wait | --wait ] sideload a local bundle (sandbox: fs.read/fs.write under $APP, audit.log; no net, no key.sign, no hooks) pilotctl appstore outdated list installed apps with a newer version in the catalogue @@ -1162,7 +1163,7 @@ func resolveAppDir(root, appID string) (string, error) { func cmdAppStoreInstall(args []string) { if len(args) < 1 { fatalHint("invalid_argument", - "usage: pilotctl appstore install [--force [--reset-state]] [--local] [--version ] [--no-wait]", + "usage: pilotctl appstore install [--force [--reset-state]] [--local] [--version ] [--no-wait | --wait ]", "missing app id or bundle dir") } target := args[0] @@ -1170,7 +1171,7 @@ func cmdAppStoreInstall(args []string) { resetState := false wantVersion := "" allowLocal := false - noWait := false + startWait := appStartWait for i := 1; i < len(args); i++ { switch args[i] { case "--force", "-f": @@ -1199,10 +1200,24 @@ func cmdAppStoreInstall(args []string) { case "--no-wait": // Return as soon as the files are in place, without waiting to // see the daemon start the app (appstore_startwait.go). - noWait = true + startWait = 0 + case "--wait": + // How long to wait for that start instead of the default, for an + // app known to take longer to open its socket. + if i+1 >= len(args) { + fatalHint("invalid_argument", "usage: --wait , e.g. --wait 60s (0 is --no-wait)", "--wait needs a value") + return + } + d, err := time.ParseDuration(args[i+1]) + if err != nil || d < 0 { + fatalHint("invalid_argument", "usage: --wait , e.g. --wait 60s (0 is --no-wait)", "invalid --wait %q", args[i+1]) + return + } + startWait = d + i++ default: fatalHint("invalid_argument", - "available flags: --force, --reset-state, --local, --version, --no-wait", + "available flags: --force, --reset-state, --local, --version, --no-wait, --wait", "unknown install flag: %s", args[i]) } } @@ -1536,7 +1551,8 @@ func cmdAppStoreInstall(args []string) { if testHookBeforeSwap != nil { testHookBeforeSwap(finalDir) } - // Supervisor events older than this belong to the install being replaced. + // Supervisor events older than this belong to the install being replaced + // (later ones can too: see appstore_startwait.go). swapAt := time.Now() // 4. Swap. The live dir is renamed to .previous and kept there // until the new dir verifies (exact manifest, pinned binary sha, @@ -1672,16 +1688,22 @@ func cmdAppStoreInstall(args []string) { // Wait for the daemon to start the app and see how that went // (appstore_startwait.go). Not when nothing will start it: no daemon, or // a reinstall the supervisor does not act on (same version and binary, - // which it leaves running, or an older version, which it refuses). + // which it leaves running, or an older version by its ordering, which it + // refuses). var start *appStartStatus + downgrade := oldManifest != nil && supervisorVersionCompare(m.AppVersion, oldManifest.AppVersion) < 0 supervisorActs := oldManifest == nil || - (semverCompare(m.AppVersion, oldManifest.AppVersion) >= 0 && - (m.AppVersion != oldManifest.AppVersion || m.Binary.SHA256 != oldManifest.Binary.SHA256)) - if !noWait && supervisorActs && daemonSocketReachable() { + (!downgrade && (m.AppVersion != oldManifest.AppVersion || m.Binary.SHA256 != oldManifest.Binary.SHA256)) + if startWait > 0 && supervisorActs && daemonSocketReachable() { if !jsonOutput { - fmt.Fprintf(os.Stderr, "installed %s v%s; waiting up to %s for the daemon to start it (--no-wait skips this)...\n", m.ID, m.AppVersion, appStartWait) - } - st := waitForAppStart(finalDir, swapAt, replacing, appStartWait) + fmt.Fprintf(os.Stderr, "installed %s v%s; waiting up to %s for the daemon to start it (--no-wait skips this)...\n", m.ID, m.AppVersion, startWait) + } + st := waitForAppStart(appStartTarget{ + Dir: finalDir, + Since: swapAt, + Version: m.AppVersion, + BinarySHA256: m.Binary.SHA256, + }, startWait) start = &st } @@ -1738,10 +1760,15 @@ func cmdAppStoreInstall(args []string) { fmt.Println(" misbehave at the syscall level. Only install paths from sources you trust.") } failIfNotStarted() - if start != nil { + switch { + case start != nil: + // Says what was seen, including that the daemon has not picked the + // app up yet; the rescan note below would contradict it. fmt.Println(start.startNote(m.ID)) - } - if start == nil || !start.Picked { + case downgrade: + fmt.Printf("note: v%s is older than the v%s it replaced; a running daemon does not switch an app to an older\n", m.AppVersion, oldManifest.AppVersion) + fmt.Println(" version, so it starts this one when the daemon next starts") + default: fmt.Println("note: the daemon rescans the install root periodically —") fmt.Println(" this app will be picked up within ~30s (no daemon restart needed)") } diff --git a/cmd/pilotctl/appstore_startwait.go b/cmd/pilotctl/appstore_startwait.go index 1b4213f6..ef23fbfe 100644 --- a/cmd/pilotctl/appstore_startwait.go +++ b/cmd/pilotctl/appstore_startwait.go @@ -9,6 +9,7 @@ import ( "net" "os" "path/filepath" + "strconv" "strings" "time" ) @@ -22,23 +23,36 @@ import ( // and the install output said nothing. // // After a successful install, with a daemon to start the app, install now -// watches the app dir for up to appStartWait and reports one of: +// watches the app dir for up to appStartWait (--wait) and reports one of: // // - started: the supervisor spawned the app and its socket is there. -// - failed: the supervisor suspended it, or it exited at least twice -// without its socket being there. install exits non-zero. -// - starting: neither, by the deadline. Not a failure: an app that takes -// longer than the wait to open its socket is healthy. +// - failed: the supervisor suspended it, it exited at least twice without +// its socket being there, or the supervisor refused it as a downgrade. +// install exits non-zero. +// - starting: none of these, by the deadline. Not a failure: an app that +// takes longer than the wait to open its socket is healthy. // -// Everything is read from the app dir (supervisor.log, .suspended, -// app.sock), like `list` and `status` do: pilotctl has no channel to the -// supervisor. The supervisor only suspends an app after more than five exits -// in a minute, 31s at the earliest, so waiting for .suspended alone would -// either miss the failure or cost every install half a minute; two exits are -// there after about 3s. - -// appStartWait bounds how long install waits for the app's first start. -// appStartPoll is how often it looks. Vars so tests can shorten them. +// Everything is read from the app dir (supervisor.log, app.sock), like `list` +// and `status` do: pilotctl has no channel to the supervisor. The supervisor +// only suspends an app after more than five exits in a minute, 31s at the +// earliest, so waiting for a suspend alone would either miss the failure or +// cost every install half a minute; two exits are there after about 3s. +// +// Which lines are the new install's. supervisor.log is carried into the new +// install, and when an install is replaced the supervisor keeps running the +// old instance until its next rescan, with the same log. So lines written +// after the swap can still be the old instance's: the end of its crash loop +// (exits, then a suspend and its .suspended marker), and the exit it logs +// when the rescan stops it, often after the new instance's supervise-start +// because it gets up to 3s to shut down. Lines name no instance, but the new +// instance's supervise-start and spawn carry the sha256 of the binary it +// runs, which is the installed manifest's. So nothing counts before one of +// those; an exit counts only when it ends a start attempt of the new +// instance; and a suspend only when it follows one of its exits. + +// appStartWait is how long install waits for the app's first start unless +// --wait says otherwise. appStartPoll is how often it looks. Vars so tests +// can shorten them. var ( appStartWait = 20 * time.Second appStartPoll = 200 * time.Millisecond @@ -55,16 +69,26 @@ const ( // delay, means the app does not come up on its own. const appStartExitsForFailure = 2 +// appStartTarget is the install whose first start is watched. +type appStartTarget struct { + Dir string // the app dir + Since time.Time // when the install was swapped in + Version string // the installed manifest's app_version + BinarySHA256 string // the installed manifest's binary sha256 +} + // appStartStatus is what install saw of the app's first start. type appStartStatus struct { - State string // appStartStarted, appStartFailed or appStartStarting - Waited time.Duration - Picked bool // the supervisor has logged something for this install - Spawns int // spawn events since the install - Exits int // exit events since the install - ExitCode int // exit code of the last of them - Suspended bool // the supervisor gave up on the app - LastEvent string // last supervisor.log line since the install, as written + State string // appStartStarted, appStartFailed or appStartStarting + Waited time.Duration + Picked bool // the supervisor has started (or refused) this install + Spawns int // spawns of this install + Exits int // exits of this install + ExitCode int // exit code of the last of them + StartError string // why the daemon could not run the binary at its last attempt (spawn-fail, verify-fail) + Suspended bool // the supervisor gave up on the app + Refusal string // the supervisor's reason for refusing this install as a downgrade + LastEvent string // last supervisor.log line of this install, as written } // supervisorEvent is the part of a supervisor.log line install looks at. @@ -73,58 +97,137 @@ type supervisorEvent struct { Event string `json:"event"` ExitCode int `json:"exit_code"` Reason string `json:"reason"` + SHA256 string `json:"sha256"` } -// readAppStart reads the app dir once. since is when the new install was -// swapped in: older log lines belong to a previous install, whose log is -// carried over. replaced is true when an install was replaced: the instance -// the supervisor stops for it logs one exit of its own. -func readAppStart(appDir string, since time.Time, replaced bool) appStartStatus { - var st appStartStatus - if f, err := os.Open(filepath.Join(appDir, "supervisor.log")); err == nil { // #nosec G304 -- //supervisor.log +// supervisorLogLines returns the lines of the app's supervisor.log, oldest +// first. The supervisor rotates the log to supervisor.log.1 once it is 10MB; +// when that happened during the wait, the start of it is there. +func supervisorLogLines(appDir string, since time.Time) []string { + var lines []string + for _, name := range []string{"supervisor.log.1", "supervisor.log"} { + path := filepath.Join(appDir, name) + if name != "supervisor.log" { + if fi, err := os.Stat(path); err != nil || fi.ModTime().Before(since) { + continue + } + } + f, err := os.Open(path) // #nosec G304 -- //supervisor.log[.1] + if err != nil { + continue + } sc := bufio.NewScanner(f) sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) for sc.Scan() { - line := strings.TrimSpace(sc.Text()) - var ev supervisorEvent - if line == "" || json.Unmarshal([]byte(line), &ev) != nil || ev.At.Before(since) { + if line := strings.TrimSpace(sc.Text()); line != "" { + lines = append(lines, line) + } + } + _ = f.Close() + } + return lines +} + +// readAppStart reads the app dir once. +func readAppStart(tg appStartTarget) appStartStatus { + var st appStartStatus + var ( + ours bool // the new instance's supervise loop has started + attempt bool // a start attempt of the new instance has not exited yet + ended bool // its last attempt has ended (exit, verify-fail): a suspend now is its own + noProcess bool // the open attempt failed before a process ran + ) + for _, line := range supervisorLogLines(tg.Dir, tg.Since) { + var ev supervisorEvent + if json.Unmarshal([]byte(line), &ev) != nil || ev.At.Before(tg.Since) { + continue + } + thisBinary := ev.SHA256 == tg.BinarySHA256 + switch ev.Event { + case "downgrade-refused": + // Written on every rescan that finds a manifest older than the + // version the supervisor runs, which can be newer than the one + // this install replaced. It names no binary; the reason names + // the refused version. + if !refusesVersion(ev.Reason, tg.Version) { + continue + } + st.Refusal = ev.Reason + case "supervise-start": + if !thisBinary { + continue + } + ours, attempt, ended, noProcess = true, false, false, false + st.Refusal = "" + case "spawn": + if !thisBinary { + continue // the old instance, restarting before the rescan replaced it + } + ours, attempt, ended, noProcess = true, true, false, false + st.Spawns++ + st.StartError = "" + case "spawn-fail": + if !ours { + continue + } + // The exec failed; an exit -1 follows. + attempt, noProcess = true, true + st.StartError = ev.Reason + case "verify-fail": + if !ours || !thisBinary { + continue + } + if strings.HasPrefix(ev.Reason, "spawn-time:") { + // The check just before exec; an exit -1 follows. + attempt, noProcess = true, true + } else { + // Retried after a backoff; suspended after 10 in a row. + ended = true + } + st.StartError = ev.Reason + case "exit": + if !attempt { + continue // the old instance: stopped by the rescan, or crashing before it + } + st.Exits++ + st.ExitCode = ev.ExitCode + afterNoProcess := noProcess + attempt, ended, noProcess = false, true, false + if afterNoProcess { + // The exit -1 after a spawn-fail or verify-fail says nothing + // that line did not; keep that one as the last event. + st.Picked = true continue } - if ev.Event == "installed" { - continue // written by pilotctl itself + case "suspend": + if !ended { + continue // the end of the old instance's crash loop } - st.Picked = true - st.LastEvent = line - switch ev.Event { - case "spawn": - st.Spawns++ - case "exit": - st.Exits++ - st.ExitCode = ev.ExitCode - case "suspend": - st.Suspended = true - case "resume": - st.Suspended = false + st.Suspended = true + case "resume": + if !ours { + continue } + st.Suspended, ended = false, false + default: + continue } - _ = f.Close() - } - // The marker of a previous install can be carried into this one before - // the supervisor clears it, so only one written since the swap counts. - if fi, err := os.Stat(filepath.Join(appDir, ".suspended")); err == nil && !fi.ModTime().Before(since) { - st.Suspended = true - } - _, sockErr := os.Stat(filepath.Join(appDir, "app.sock")) - needExits := appStartExitsForFailure - if replaced { - needExits++ + st.Picked = true + st.LastEvent = line } + // The .suspended marker is not read: it names no instance either, and + // the old instance writes it into the new install's dir when its crash + // loop ends after the swap. The supervisor logs the suspend before it + // writes the marker, so the log has everything the marker would say. + _, sockErr := os.Stat(filepath.Join(tg.Dir, "app.sock")) switch { + case st.Refusal != "": + st.State = appStartFailed case st.Suspended: st.State = appStartFailed case sockErr == nil && st.Spawns > 0: st.State = appStartStarted - case sockErr != nil && st.Exits >= needExits: + case sockErr != nil && st.Exits >= appStartExitsForFailure: st.State = appStartFailed default: st.State = appStartStarting @@ -132,12 +235,19 @@ func readAppStart(appDir string, since time.Time, replaced bool) appStartStatus return st } +// refusesVersion reports whether a downgrade-refused reason is about +// version. The supervisor words it "refusing (existing )", +// after "rescan: " when the rescan refused it. +func refusesVersion(reason, version string) bool { + return strings.Contains(reason, "refusing "+version+" (") +} + // waitForAppStart polls the app dir until the start is decided either way, // or wait has passed. -func waitForAppStart(appDir string, since time.Time, replaced bool, wait time.Duration) appStartStatus { +func waitForAppStart(tg appStartTarget, wait time.Duration) appStartStatus { begin := time.Now() for { - st := readAppStart(appDir, since, replaced) + st := readAppStart(tg) st.Waited = time.Since(begin) if st.State != appStartStarting || st.Waited >= wait { return st @@ -158,11 +268,65 @@ func daemonSocketReachable() bool { return true } +// supervisorVersionCompare orders app versions the way the daemon's +// supervisor does when it decides whether an install on disk replaces the +// app it runs (compareVersions in the app-store module's plugin/appstore, +// which is not exported): MAJOR.MINOR.PATCH numerically, then a release +// above its prereleases, then prereleases as plain strings. semverCompare +// ignores prereleases, which is fine for "does the catalogue have a newer +// version", but not here: 1.0.0 → 1.0.0-beta.1 is equal there and a +// downgrade the supervisor refuses, so install would wait for a start that +// cannot come. +func supervisorVersionCompare(a, b string) int { + if a == b { + return 0 + } + aNum, aPre, _ := strings.Cut(a, "-") + bNum, bPre, _ := strings.Cut(b, "-") + aParts, bParts := strings.Split(aNum, "."), strings.Split(bNum, ".") + part := func(parts []string, i int) int { + if i >= len(parts) { + return 0 + } + n, err := strconv.Atoi(parts[i]) + if err != nil { + return 0 + } + return n + } + for i := 0; i < 3; i++ { + if av, bv := part(aParts, i), part(bParts, i); av != bv { + if av < bv { + return -1 + } + return 1 + } + } + switch { + case aPre == "" && bPre != "": + return 1 + case aPre != "" && bPre == "": + return -1 + } + return strings.Compare(aPre, bPre) +} + // startFailure words a failed start: what happened, and where to look. func (st appStartStatus) startFailure(appID string) (what, hint string) { - if st.Suspended { + if st.Refusal != "" { + what = "the daemon runs a newer version and refuses to replace it with an older one (" + st.Refusal + ")" + hint = "the files are installed, but the daemon keeps the version it was running (which it cannot restart from these files) " + + "and starts this one only when the daemon itself restarts (`pilotctl daemon stop`, then `pilotctl daemon start`). " + + "To stay on the newer version instead, install a version at least as new as the one the daemon runs, with --force. " + + "To remove it: `pilotctl appstore uninstall " + appID + " --yes`." + return what, hint + } + switch { + case st.Suspended: what = "the daemon suspended it after repeated crashes" - } else { + case st.StartError != "": + what = fmt.Sprintf("the daemon could not run it (%d attempts; last: %s)", st.Exits, st.StartError) + default: what = fmt.Sprintf("it exited %d times at start (last exit code %d)", st.Exits, st.ExitCode) } hint = "the files are installed, the app is not running. " @@ -187,6 +351,8 @@ func (st appStartStatus) startNote(appID string) string { return fmt.Sprintf("started: the daemon is running %s (socket ready after %s)", appID, waited) case !st.Picked: return fmt.Sprintf("note: the daemon has not started %s after %s; it picks new apps up on its rescan. Check with `pilotctl appstore status %s`", appID, waited, appID) + case st.StartError != "": + return fmt.Sprintf("note: the daemon could not run %s yet (%s); it keeps retrying. Check with `pilotctl appstore status %s` and `pilotctl appstore audit %s`", appID, st.StartError, appID, appID) case st.Exits > 0: return fmt.Sprintf("note: %s is not ready after %s and has exited %d time(s) (last exit code %d); the daemon is restarting it. Check with `pilotctl appstore status %s` and `pilotctl appstore audit %s`", appID, waited, st.Exits, st.ExitCode, appID, appID) default: diff --git a/cmd/pilotctl/main.go b/cmd/pilotctl/main.go index a1e3f69c..f708c7e4 100644 --- a/cmd/pilotctl/main.go +++ b/cmd/pilotctl/main.go @@ -1686,7 +1686,9 @@ Agent tool discovery: App store (install + call local capability apps; full help: pilotctl appstore help): pilotctl appstore catalogue list apps available for one-command install pilotctl appstore view [--all-changelog] app detail page (description, methods, permissions) - pilotctl appstore install [--force] install by catalogue ID (fetch + verify + extract) + pilotctl appstore install [--force] [--no-wait | --wait ] + install by catalogue ID (fetch + verify + extract) + and wait up to 20s for the app's first start pilotctl appstore list list installed apps + their IPC methods pilotctl appstore call [json-args] dispatch an IPC call into an app pilotctl appstore status|caps|audit|restart|uninstall @@ -2583,7 +2585,7 @@ func contextCatalog() map[string]interface{} { "subcommands": map[string]interface{}{ "catalogue": map[string]interface{}{"args": []string{}, "description": "List apps available for one-command install (alias: catalog)"}, "view": map[string]interface{}{"args": []string{"", "[--all-changelog]"}, "description": "Detail page: description, vendor, changelog, size, source, methods, permissions (installed or not)"}, - "install": map[string]interface{}{"args": []string{" [--force]", "| --local [--force]"}, "description": "Install by catalogue ID (fetch + verify + extract), or sideload a local bundle with --local"}, + "install": map[string]interface{}{"args": []string{" [--force]", "| --local [--force]", "[--no-wait | --wait ]"}, "description": "Install by catalogue ID (fetch + verify + extract), or sideload a local bundle with --local. With a daemon running, waits up to 20s (--wait ) for the app's first start and exits non-zero (app_start_failed) if it crashed at start, was suspended, or was refused as older than the version the daemon runs; --no-wait returns at once"}, "list": map[string]interface{}{"args": []string{}, "description": "List installed apps and the IPC methods each exposes"}, "call": map[string]interface{}{"args": []string{"", "", "[json-args]", "[--timeout ]"}, "description": "Dispatch an IPC call into an app (default timeout 120s; $PILOT_APPSTORE_CALL_TIMEOUT)"}, "status": map[string]interface{}{"args": []string{""}, "description": "Deep-dive on one app's pinned state"}, diff --git a/cmd/pilotctl/zz_appstore_cmds_test.go b/cmd/pilotctl/zz_appstore_cmds_test.go index 3887dd76..e3183753 100644 --- a/cmd/pilotctl/zz_appstore_cmds_test.go +++ b/cmd/pilotctl/zz_appstore_cmds_test.go @@ -506,8 +506,11 @@ func TestCmdAppStoreVerifyHappyPath(t *testing.T) { } func TestCmdAppStoreInstallHappyPath(t *testing.T) { - root := t.TempDir() - t.Setenv("PILOT_APPSTORE_ROOT", root) + // isolateAppStoreTest points PILOT_SOCKET at a path nothing listens on: + // with a daemon running on this machine, install would otherwise wait + // for it to start an app it never sees. It also keeps telemetry and the + // catalogue off the network. + root := isolateAppStoreTest(t) bundleDir, _ := makeBundle(t, "io.test.install") prev := jsonOutput @@ -538,8 +541,7 @@ func TestCmdAppStoreInstallHappyPath(t *testing.T) { } func TestCmdAppStoreInstallRefusesDuplicate(t *testing.T) { - root := t.TempDir() - t.Setenv("PILOT_APPSTORE_ROOT", root) + isolateAppStoreTest(t) // no daemon: see TestCmdAppStoreInstallHappyPath bundleDir, _ := makeBundle(t, "io.test.dup") prev := jsonOutput defer func() { jsonOutput = prev }() @@ -701,8 +703,7 @@ func TestCmdAppStoreCapsNoCapsManifest(t *testing.T) { // it doesn't actually connect (no daemon needed). Both "help" and // "list" with no apps should exit cleanly. func TestCmdAppStoreInstallTextMode(t *testing.T) { - root := t.TempDir() - t.Setenv("PILOT_APPSTORE_ROOT", root) + isolateAppStoreTest(t) // no daemon: see TestCmdAppStoreInstallHappyPath bundleDir, _ := makeBundle(t, "io.test.install.text") prev := jsonOutput defer func() { jsonOutput = prev }() diff --git a/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go b/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go index a3026e16..5e03fc72 100644 --- a/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go +++ b/cmd/pilotctl/zz_appstore_startwait_supervisor_test.go @@ -16,19 +16,17 @@ import ( "github.com/pilot-protocol/app-store/plugin/appstore" ) -// installUnderRealSupervisor installs a local bundle whose binary is the -// given shell script while the daemon's real app supervisor (the app-store -// module, with the daemon's 2s rescan shortened) watches the install root. -// Unlike the tests in zz_appstore_startwait_test.go, nothing here writes -// supervisor.log by hand: what install reads is what the supervisor wrote. -func installUnderRealSupervisor(t *testing.T, id, script string) (report map[string]any, stderr string, failure *trappedFatal) { +// startRealSupervisor isolates the install root and runs the daemon's real +// app supervisor (the app-store module, with the daemon's 2s rescan +// shortened to rescan) on it. Unlike the tests in +// zz_appstore_startwait_test.go, nothing here writes supervisor.log by hand: +// what install reads is what the supervisor wrote. +func startRealSupervisor(t *testing.T, rescan time.Duration) (root string) { t.Helper() - root := isolateAppStoreTest(t) - t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) - + root = isolateAppStoreTest(t) svc := appstore.NewService(appstore.Config{ InstallRoot: root, - RescanInterval: 100 * time.Millisecond, + RescanInterval: rescan, Logger: log.New(io.Discard, "", 0), }) ctx, cancel := context.WithCancel(context.Background()) @@ -38,27 +36,64 @@ func installUnderRealSupervisor(t *testing.T, id, script string) (report map[str } t.Cleanup(func() { cancel() - // The healthy test app runs for as long as its socket file exists. - _ = os.Remove(filepath.Join(root, id, "app.sock")) + // A healthy test app runs for as long as its socket file exists. + socks, _ := filepath.Glob(filepath.Join(root, "*", "app.sock")) + for _, s := range socks { + _ = os.Remove(s) + } stopCtx, stopCancel := context.WithTimeout(context.Background(), 20*time.Second) defer stopCancel() _ = svc.Stop(stopCtx) }) + return root +} + +// realBundle writes a local bundle whose binary is the given shell script. +// writeVersionedBundle writes "#!/bin/sh\necho \n". The supervisor runs +// in this process and hands the app this process's stderr, which is the pipe +// runTrapped captures while an install runs; the app lets go of it at once, +// or the capture would wait for the app to exit. tag makes the binary, and +// so its sha256, differ between versions. +func realBundle(t *testing.T, id, version, tag, script string) string { + t.Helper() + return writeVersionedBundle(t, id, version, tag+" >/dev/null\nexec >/dev/null 2>&1\n"+script) +} - // writeVersionedBundle writes "#!/bin/sh\necho \n". The supervisor - // runs in this process and hands the app this process's stderr, which is - // the pipe runTrapped captures while the install runs; the app lets go of - // it at once, or the capture would wait for the app to exit. - bundle := writeVersionedBundle(t, id, "1.0.0", "starting >/dev/null\nexec >/dev/null 2>&1\n"+script) +// installUnderDaemon runs a JSON-mode install with a daemon socket +// listening (the fake daemon serves one connection, so each install gets +// its own). +func installUnderDaemon(t *testing.T, args ...string) (report map[string]any, stderr string, failure *trappedFatal) { + t.Helper() + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) var stdout string withJSON(func() { - stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local"}) }) + stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall(args) }) }) if err := json.Unmarshal([]byte(stdout), &report); err != nil { t.Fatalf("install report: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) } - log, _ := os.ReadFile(filepath.Join(root, id, "supervisor.log")) + return report, stderr, failure +} + +func logSupervisor(t *testing.T, appDir string) { + t.Helper() + log, _ := os.ReadFile(filepath.Join(appDir, "supervisor.log")) t.Logf("supervisor.log:\n%s", log) +} + +// healthyScript opens its "socket" (the supervisor and pilotctl only look for +// the path) and keeps running, like an app does, until the file is removed. +const healthyScript = `while [ $# -gt 0 ]; do if [ "$1" = "--socket" ]; then sock="$2"; fi; shift; done +: > "$sock" +while [ -e "$sock" ]; do sleep 0.2; done` + +// installUnderRealSupervisor installs a local bundle whose binary is the +// given shell script under the real supervisor. +func installUnderRealSupervisor(t *testing.T, id, script string) (report map[string]any, stderr string, failure *trappedFatal) { + t.Helper() + root := startRealSupervisor(t, 100*time.Millisecond) + report, stderr, failure = installUnderDaemon(t, realBundle(t, id, "1.0.0", "starting", script), "--local") + logSupervisor(t, filepath.Join(root, id)) return report, stderr, failure } @@ -86,12 +121,7 @@ func TestAppStoreInstallUnderRealSupervisorHealthyApp(t *testing.T) { if testing.Short() { t.Skip("starts a real process") } - // Opens its "socket" (the supervisor and pilotctl only look for the - // path) and keeps running, like an app does, until the file is removed. - script := `while [ $# -gt 0 ]; do if [ "$1" = "--socket" ]; then sock="$2"; fi; shift; done -: > "$sock" -while [ -e "$sock" ]; do sleep 0.2; done` - report, stderr, f := installUnderRealSupervisor(t, "io.test.realhealthy", script) + report, stderr, f := installUnderRealSupervisor(t, "io.test.realhealthy", healthyScript) if f != nil { t.Fatalf("install of a healthy app failed: %+v\n%s", f, stderr) } @@ -99,3 +129,108 @@ while [ -e "$sock" ]; do sleep 0.2; done` t.Fatalf("report = %v", report) } } + +// An upgrade of a running app: the replaced instance exits after the swap +// (its socket went with the old dir) and is stopped by the rescan. None of +// that is the new install's. +func TestAppStoreUpgradeUnderRealSupervisor(t *testing.T) { + if testing.Short() { + t.Skip("starts real processes") + } + shortStartWait(t, 10*time.Second) + const id = "io.test.realupgrade" + // A rescan slower than the old app's 0.2s socket check, so the old + // instance has exited (and is waiting out its restart delay) when the + // rescan replaces it. + root := startRealSupervisor(t, 500*time.Millisecond) + appDir := filepath.Join(root, id) + if report, stderr, f := installUnderDaemon(t, realBundle(t, id, "1.0.0", "v1", healthyScript), "--local"); f != nil || report["start_state"] != appStartStarted { + t.Fatalf("install v1: %+v %v\n%s", f, report, stderr) + } + report, stderr, f := installUnderDaemon(t, realBundle(t, id, "2.0.0", "v2", healthyScript), "--local", "--force") + logSupervisor(t, appDir) + if f != nil { + t.Fatalf("upgrade failed: %+v\n%s", f, stderr) + } + if report["start_state"] != appStartStarted { + t.Fatalf("report = %v", report) + } + if _, has := report["start_exits"]; has { + t.Errorf("the replaced instance's exit was counted: %v", report) + } +} + +// The supervisor compares an install with the version it runs, which can be +// newer than the one on disk: here it runs v2.0.0 and refused the v1.0.0 +// installed over it, so it refuses v1.5.0 as well. install reports that at +// once instead of waiting for a start that will not come. +func TestAppStoreInstallUnderRealSupervisorDowngradeRefused(t *testing.T) { + if testing.Short() { + t.Skip("starts a real process") + } + shortStartWait(t, 10*time.Second) + const id = "io.test.realrefused" + root := startRealSupervisor(t, 100*time.Millisecond) + appDir := filepath.Join(root, id) + if report, stderr, f := installUnderDaemon(t, realBundle(t, id, "2.0.0", "v2", healthyScript), "--local"); f != nil || report["start_state"] != appStartStarted { + t.Fatalf("install v2: %+v %v\n%s", f, report, stderr) + } + if report, stderr, f := installUnderDaemon(t, realBundle(t, id, "1.0.0", "v1", healthyScript), "--local", "--force"); f != nil { + t.Fatalf("install v1: %+v %v\n%s", f, report, stderr) + } + begin := time.Now() + report, stderr, f := installUnderDaemon(t, realBundle(t, id, "1.5.0", "v1.5", healthyScript), "--local", "--force") + logSupervisor(t, appDir) + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("install v1.5 = %+v, want app_start_failed\nreport: %v\nstderr: %s", f, report, stderr) + } + if !strings.Contains(f.Message, "refusing 1.5.0 (existing 2.0.0)") { + t.Errorf("message = %q", f.Message) + } + if took := time.Since(begin); took > 5*time.Second { + t.Errorf("took %s to see the refusal", took) + } +} + +// install waits exactly when the supervisor will act: it orders a +// prerelease below its release, as the supervisor does. +func TestAppStoreInstallUnderRealSupervisorPrereleaseOrder(t *testing.T) { + if testing.Short() { + t.Skip("starts real processes") + } + shortStartWait(t, 10*time.Second) + const id = "io.test.realprerelease" + root := startRealSupervisor(t, 100*time.Millisecond) + appDir := filepath.Join(root, id) + if report, stderr, f := installUnderDaemon(t, realBundle(t, id, "1.0.0-beta.1", "beta1", healthyScript), "--local"); f != nil || report["start_state"] != appStartStarted { + t.Fatalf("install 1.0.0-beta.1: %+v %v\n%s", f, report, stderr) + } + // The release is newer than its prerelease: the supervisor switches to it. + report, stderr, f := installUnderDaemon(t, realBundle(t, id, "1.0.0", "release", healthyScript), "--local", "--force") + if f != nil || report["start_state"] != appStartStarted { + logSupervisor(t, appDir) + t.Fatalf("1.0.0-beta.1 → 1.0.0: %+v %v\n%s", f, report, stderr) + } + // A prerelease of the running release is older: no wait, and the + // supervisor does refuse it. + begin := time.Now() + report, stderr, f = installUnderDaemon(t, realBundle(t, id, "1.0.0-beta.2", "beta2", healthyScript), "--local", "--force") + if f != nil { + t.Fatalf("1.0.0 → 1.0.0-beta.2: %+v\n%s", f, stderr) + } + if _, has := report["start_state"]; has || time.Since(begin) > 5*time.Second { + t.Errorf("waited for a start the supervisor refuses: %v", report) + } + deadline := time.Now().Add(5 * time.Second) + for { + log, _ := os.ReadFile(filepath.Join(appDir, "supervisor.log")) + if strings.Contains(string(log), "refusing 1.0.0-beta.2 (existing 1.0.0)") { + break + } + if time.Now().After(deadline) { + logSupervisor(t, appDir) + t.Fatal("the supervisor did not refuse 1.0.0-beta.2, so install should have waited for it") + } + time.Sleep(50 * time.Millisecond) + } +} diff --git a/cmd/pilotctl/zz_appstore_startwait_test.go b/cmd/pilotctl/zz_appstore_startwait_test.go index 4c1220f9..e44e67ea 100644 --- a/cmd/pilotctl/zz_appstore_startwait_test.go +++ b/cmd/pilotctl/zz_appstore_startwait_test.go @@ -13,12 +13,15 @@ import ( ) // supLog appends supervisor.log lines the way the daemon's supervisor writes -// them. +// them. Tests call it from goroutines that play the supervisor, so failures +// are reported with t.Error: t.Fatal must not be called off the test's own +// goroutine. func supLog(t *testing.T, appDir string, at time.Time, events ...string) { t.Helper() f, err := os.OpenFile(filepath.Join(appDir, "supervisor.log"), os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) if err != nil { - t.Fatal(err) + t.Error(err) + return } defer f.Close() for _, ev := range events { @@ -28,29 +31,50 @@ func supLog(t *testing.T, appDir string, at time.Time, events ...string) { line += "," + extra } if _, err := f.WriteString(line + "}\n"); err != nil { - t.Fatal(err) + t.Error(err) + return } } } +// touch creates an empty file; like supLog, it is called from goroutines. func touch(t *testing.T, path string) { t.Helper() if err := os.WriteFile(path, nil, 0o600); err != nil { - t.Fatal(err) + t.Error(err) } } +// ofBinary returns a supervisor.log event as the instance running the binary +// with this sha256 writes it: supervise-start and spawn carry the sha. +func ofBinary(sha, event string) string { + if strings.Contains(event, " ") { // already has fields + return event + `,"sha256":"` + sha + `"` + } + return event + ` "sha256":"` + sha + `"` +} + +const ( + testNewSHA = "1111111111111111111111111111111111111111111111111111111111111111" + testOldSHA = "2222222222222222222222222222222222222222222222222222222222222222" +) + func TestReadAppStart(t *testing.T) { since := time.Now().Add(-time.Minute) before, after := since.Add(-time.Hour), since.Add(time.Second) const exit1 = `exit "exit_code":1` + var ( + start = ofBinary(testNewSHA, "supervise-start") + spawn = ofBinary(testNewSHA, "spawn") + upgraded = ofBinary(testNewSHA, "upgrade-applied") + oldSpawn = ofBinary(testOldSHA, "spawn") + ) for _, tc := range []struct { - name string - replaced bool - setup func(t *testing.T, dir string) - want string - check func(t *testing.T, st appStartStatus) + name string + setup func(t *testing.T, dir string) + want string + check func(t *testing.T, st appStartStatus) }{ {name: "nothing yet", setup: func(*testing.T, string) {}, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { @@ -59,73 +83,153 @@ func TestReadAppStart(t *testing.T) { } }}, {name: "only pilotctl's own install line", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "installed") + supLog(t, dir, after, ofBinary(testNewSHA, "installed")) }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { if st.Picked || st.LastEvent != "" { t.Errorf("pilotctl's install line counted as a supervisor event: %+v", st) } }}, {name: "spawned, socket not there yet", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", "spawn") + supLog(t, dir, after, start, spawn) }, want: appStartStarting}, {name: "spawned and socket there", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", "spawn") + supLog(t, dir, after, start, spawn) touch(t, filepath.Join(dir, "app.sock")) }, want: appStartStarted}, {name: "socket without a spawn since the install is a leftover", setup: func(t *testing.T, dir string) { - supLog(t, dir, before, "supervise-start", "spawn") + supLog(t, dir, before, start, spawn) touch(t, filepath.Join(dir, "app.sock")) }, want: appStartStarting}, {name: "one exit is not a failure", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", "spawn", exit1) + supLog(t, dir, after, start, spawn, exit1) }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { if st.Exits != 1 || st.ExitCode != 1 { t.Errorf("exits=%d code=%d", st.Exits, st.ExitCode) } }}, {name: "two exits and no socket", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", "spawn", exit1, "spawn", `exit "exit_code":3`) + supLog(t, dir, after, start, spawn, exit1, spawn, `exit "exit_code":3`) }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { if st.Exits != 2 || st.ExitCode != 3 || !strings.Contains(st.LastEvent, `"exit_code":3`) { t.Errorf("%+v", st) } }}, {name: "exited once, then came up", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", "spawn", exit1, "spawn") + supLog(t, dir, after, start, spawn, exit1, spawn) touch(t, filepath.Join(dir, "app.sock")) }, want: appStartStarted}, {name: "exits of the previous install do not count", setup: func(t *testing.T, dir string) { - supLog(t, dir, before, "spawn", exit1, "spawn", exit1, "spawn", exit1, "suspend") - supLog(t, dir, after, "supervise-start", "spawn") + supLog(t, dir, before, oldSpawn, exit1, oldSpawn, exit1, oldSpawn, exit1, "suspend") + supLog(t, dir, after, start, spawn) }, want: appStartStarting}, - {name: "replaced install: the stopped old instance logs an exit too", replaced: true, setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "upgrade-applied", "exit", "supervise-start", "spawn", exit1) + + // The old instance runs until the supervisor's rescan replaces it, and + // writes to the same log after the swap. + {name: "upgrade: the old instance's crash loop is suspended after the swap", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, oldSpawn, exit1, `suspend "reason":">5 crashes in 1m0s"`) + touch(t, filepath.Join(dir, ".suspended")) + supLog(t, dir, after, upgraded, start, spawn) + touch(t, filepath.Join(dir, "app.sock")) + }, want: appStartStarted, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 0 || st.Suspended || st.Spawns != 1 { + t.Errorf("the old instance's events were counted: %+v", st) + } + }}, + {name: "upgrade: the old instance's suspend, the new one not up yet", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, exit1, `suspend "reason":">5 crashes in 1m0s"`, upgraded, start, spawn) }, want: appStartStarting}, - {name: "replaced install: three exits", replaced: true, setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "upgrade-applied", "exit", "supervise-start", "spawn", exit1, "spawn", exit1) - }, want: appStartFailed}, - {name: "suspend event", setup: func(t *testing.T, dir string) { - supLog(t, dir, after, "supervise-start", `verify-fail "reason":"sha256 mismatch"`, `suspend "reason":">=10 consecutive verify failures"`) + {name: "upgrade: the old instance's events before the rescan are not the new install's", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, exit1, oldSpawn, exit1, `suspend "reason":">5 crashes in 1m0s"`) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Picked || st.LastEvent != "" { + t.Errorf("%+v", st) + } + }}, + {name: "upgrade: the old instance's exit when the rescan stops it, after the new supervise-start", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, upgraded, start, `exit "exit_code":-1`, `supervise-stop "reason":"context canceled"`, spawn, exit1) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 1 || st.ExitCode != 1 { + t.Errorf("exits=%d code=%d, want only the new instance's one", st.Exits, st.ExitCode) + } + }}, + {name: "upgrade: the new instance exits twice", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, upgraded, `exit "exit_code":-1`, start, spawn, exit1, spawn, exit1) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 2 { + t.Errorf("exits=%d, want 2", st.Exits) + } + }}, + {name: "a .suspended marker alone is the old instance's", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, spawn) + touch(t, filepath.Join(dir, ".suspended")) + }, want: appStartStarting}, + + {name: "the new instance's crash loop is suspended", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, spawn, exit1, `suspend "reason":">5 crashes in 1m0s"`) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if !st.Suspended || !strings.Contains(st.LastEvent, `"suspend"`) { + t.Errorf("%+v", st) + } + }}, + {name: "suspended after verify failures", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, ofBinary(testNewSHA, `verify-fail "reason":"sha256 mismatch"`), `suspend "reason":">=10 consecutive verify failures"`) }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { if !st.Suspended { t.Error("not marked suspended") } }}, - {name: "suspended marker written since the install", setup: func(t *testing.T, dir string) { - touch(t, filepath.Join(dir, ".suspended")) - }, want: appStartFailed}, - {name: "suspended marker carried from the previous install", setup: func(t *testing.T, dir string) { - marker := filepath.Join(dir, ".suspended") - touch(t, marker) - if err := os.Chtimes(marker, before, before); err != nil { - t.Fatal(err) + {name: "resumed by the operator", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, spawn, exit1, `suspend "reason":">5 crashes in 1m0s"`, "resume", start, spawn) + touch(t, filepath.Join(dir, "app.sock")) + }, want: appStartStarted}, + {name: "spawn-fail: the failure, not the exit -1 after it, is the last event", setup: func(t *testing.T, dir string) { + fail := `spawn-fail "reason":"fork/exec bin/app: exec format error"` + supLog(t, dir, after, start, fail, `exit "exit_code":-1`, fail, `exit "exit_code":-1`) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 2 || !strings.Contains(st.StartError, "exec format error") || !strings.Contains(st.LastEvent, `"spawn-fail"`) { + t.Errorf("%+v", st) + } + what, _ := st.startFailure("io.test.app") + if !strings.Contains(what, "could not run it") || !strings.Contains(what, "exec format error") { + t.Errorf("failure = %q", what) + } + }}, + {name: "spawn-time verify failure", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, ofBinary(testNewSHA, `verify-fail "reason":"spawn-time: sha256 mismatch"`), `exit "exit_code":-1`) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 1 || !strings.Contains(st.LastEvent, "spawn-time") { + t.Errorf("%+v", st) } + }}, + {name: "the old instance's verify failures are not the new install's", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, ofBinary(testOldSHA, `verify-fail "reason":"sha256 mismatch"`), `suspend "reason":">=10 consecutive verify failures"`) }, want: appStartStarting}, + {name: "refused as a downgrade", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, `downgrade-refused "reason":"rescan: refusing 1.5.0 (existing 2.0.0)"`) + }, want: appStartFailed, check: func(t *testing.T, st appStartStatus) { + if st.Refusal != "rescan: refusing 1.5.0 (existing 2.0.0)" || !st.Picked { + t.Errorf("%+v", st) + } + }}, + {name: "another version's refusal is not this install's", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, `downgrade-refused "reason":"rescan: refusing 1.0.0 (existing 2.0.0)"`) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Picked { + t.Errorf("%+v", st) + } + }}, + {name: "the log rotated during the wait", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, start, spawn, exit1) + if err := os.Rename(filepath.Join(dir, "supervisor.log"), filepath.Join(dir, "supervisor.log.1")); err != nil { + t.Fatal(err) + } + supLog(t, dir, after, spawn, exit1) + }, want: appStartFailed}, } { t.Run(tc.name, func(t *testing.T) { dir := t.TempDir() tc.setup(t, dir) - st := readAppStart(dir, since, tc.replaced) + st := readAppStart(appStartTarget{Dir: dir, Since: since, Version: "1.5.0", BinarySHA256: testNewSHA}) if st.State != tc.want { t.Fatalf("state = %q, want %q (%+v)", st.State, tc.want, st) } @@ -136,6 +240,30 @@ func TestReadAppStart(t *testing.T) { } } +// Must order versions exactly as compareVersions in the app-store module's +// plugin/appstore (the daemon's supervisor) does. +func TestSupervisorVersionCompare(t *testing.T) { + for _, c := range []struct { + a, b string + want int + }{ + {"1.0.0", "1.0.0", 0}, + {"1.0.1", "1.0.0", 1}, + {"1.2.0", "1.10.0", -1}, // numeric, not lexical + {"1.2", "1.2.0", 0}, // a missing part is 0 + {"1.0.0-beta.1", "1.0.0", -1}, + {"1.0.0", "1.0.0-beta.1", 1}, + {"1.0.0-beta.2", "1.0.0-beta.1", 1}, + {"1.0.0-alpha", "1.0.0-beta", -1}, + {"1.0.0-beta.10", "1.0.0-beta.9", -1}, // prereleases compare as plain strings + {"2.0.0-rc.1", "1.9.9", 1}, + } { + if got := supervisorVersionCompare(c.a, c.b); got != c.want { + t.Errorf("supervisorVersionCompare(%q, %q) = %d, want %d", c.a, c.b, got, c.want) + } + } +} + func shortStartWait(t *testing.T, wait time.Duration) { t.Helper() prevWait, prevPoll := appStartWait, appStartPoll @@ -147,15 +275,19 @@ func shortStartWait(t *testing.T, wait time.Duration) { // otherwise: an app that is merely slow is "starting", never "failed". func TestWaitForAppStart(t *testing.T) { shortStartWait(t, 0) + target := func(dir string, since time.Time) appStartTarget { + return appStartTarget{Dir: dir, Since: since, Version: "1.0.0", BinarySHA256: testNewSHA} + } + start, spawn := ofBinary(testNewSHA, "supervise-start"), ofBinary(testNewSHA, "spawn") t.Run("returns when the socket appears", func(t *testing.T) { dir := t.TempDir() since := time.Now() go func() { time.Sleep(200 * time.Millisecond) - supLog(t, dir, time.Now(), "supervise-start", "spawn") + supLog(t, dir, time.Now(), start, spawn) touch(t, filepath.Join(dir, "app.sock")) }() - st := waitForAppStart(dir, since, false, 10*time.Second) + st := waitForAppStart(target(dir, since), 10*time.Second) if st.State != appStartStarted || st.Waited > 5*time.Second { t.Fatalf("%+v", st) } @@ -165,19 +297,19 @@ func TestWaitForAppStart(t *testing.T) { since := time.Now() go func() { time.Sleep(100 * time.Millisecond) - supLog(t, dir, time.Now(), "supervise-start", "spawn", `exit "exit_code":1`) + supLog(t, dir, time.Now(), start, spawn, `exit "exit_code":1`) time.Sleep(100 * time.Millisecond) - supLog(t, dir, time.Now(), "spawn", `exit "exit_code":1`) + supLog(t, dir, time.Now(), spawn, `exit "exit_code":1`) }() - st := waitForAppStart(dir, since, false, 10*time.Second) + st := waitForAppStart(target(dir, since), 10*time.Second) if st.State != appStartFailed || st.Waited > 5*time.Second { t.Fatalf("%+v", st) } }) t.Run("a slow app is still starting at the deadline", func(t *testing.T) { dir := t.TempDir() - supLog(t, dir, time.Now(), "supervise-start", "spawn") - st := waitForAppStart(dir, time.Now().Add(-time.Second), false, 300*time.Millisecond) + supLog(t, dir, time.Now(), start, spawn) + st := waitForAppStart(target(dir, time.Now().Add(-time.Second)), 300*time.Millisecond) if st.State != appStartStarting || st.Waited < 300*time.Millisecond { t.Fatalf("%+v", st) } @@ -186,12 +318,15 @@ func TestWaitForAppStart(t *testing.T) { // installWithSupervisor installs a local bundle with a daemon socket // listening, while supervise plays the daemon's supervisor on the app dir -// once the install has put the manifest there. -func installWithSupervisor(t *testing.T, id string, supervise func(appDir string), args ...string) (root string, report map[string]any, stderr string, failure *trappedFatal) { +// once the install has put the manifest there. sha is the bundle's binary +// sha256, which the supervisor logs on supervise-start and spawn. +func installWithSupervisor(t *testing.T, id string, supervise func(appDir, sha string), args ...string) (root string, report map[string]any, stderr string, failure *trappedFatal) { t.Helper() root = isolateAppStoreTest(t) sd := newStreamDaemon(t) t.Setenv("PILOT_SOCKET", sd.path) + bundle := writeVersionedBundle(t, id, "1.0.0", "v1") + sha := sha256File(filepath.Join(bundle, "bin", "app")) appDir := filepath.Join(root, id) done := make(chan struct{}) stop := make(chan struct{}) @@ -208,10 +343,9 @@ func installWithSupervisor(t *testing.T, id string, supervise func(appDir string } } if supervise != nil { - supervise(appDir) + supervise(appDir, sha) } }() - bundle := writeVersionedBundle(t, id, "1.0.0", "v1") var stdout string withJSON(func() { stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall(append([]string{bundle, "--local"}, args...)) }) @@ -227,9 +361,9 @@ func installWithSupervisor(t *testing.T, id string, supervise func(appDir string func TestAppStoreInstallReportsStartedApp(t *testing.T) { shortStartWait(t, 10*time.Second) const id = "io.test.starts" - _, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { + _, report, stderr, f := installWithSupervisor(t, id, func(appDir, sha string) { time.Sleep(150 * time.Millisecond) // the rescan - supLog(t, appDir, time.Now(), "supervise-start", "spawn") + supLog(t, appDir, time.Now(), ofBinary(sha, "supervise-start"), ofBinary(sha, "spawn")) touch(t, filepath.Join(appDir, "app.sock")) }) if f != nil { @@ -245,10 +379,10 @@ func TestAppStoreInstallReportsStartedApp(t *testing.T) { func TestAppStoreInstallFailsForAppThatCrashesAtStart(t *testing.T) { shortStartWait(t, 10*time.Second) const id = "io.test.crashes" - root, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { - supLog(t, appDir, time.Now(), "supervise-start", "spawn", `exit "exit_code":1`) + root, report, stderr, f := installWithSupervisor(t, id, func(appDir, sha string) { + supLog(t, appDir, time.Now(), ofBinary(sha, "supervise-start"), ofBinary(sha, "spawn"), `exit "exit_code":1`) time.Sleep(100 * time.Millisecond) // the supervisor's restart delay - supLog(t, appDir, time.Now(), "spawn", `exit "exit_code":1`) + supLog(t, appDir, time.Now(), ofBinary(sha, "spawn"), `exit "exit_code":1`) }) if f == nil || f.Code != "app_start_failed" { t.Fatalf("install = %+v, want app_start_failed\nstderr: %s", f, stderr) @@ -274,8 +408,10 @@ func TestAppStoreInstallFailsForAppThatCrashesAtStart(t *testing.T) { func TestAppStoreInstallFailsForSuspendedApp(t *testing.T) { shortStartWait(t, 10*time.Second) const id = "io.test.suspended" - _, report, stderr, f := installWithSupervisor(t, id, func(appDir string) { - supLog(t, appDir, time.Now(), "supervise-start", `suspend "reason":">5 crashes in 1m0s"`) + _, report, stderr, f := installWithSupervisor(t, id, func(appDir, sha string) { + // A crash record carried over from an earlier instance can suspend + // the app at its first exit. + supLog(t, appDir, time.Now(), ofBinary(sha, "supervise-start"), ofBinary(sha, "spawn"), `exit "exit_code":1`, `suspend "reason":">5 crashes in 1m0s"`) touch(t, filepath.Join(appDir, ".suspended")) }) if f == nil || f.Code != "app_start_failed" || !strings.Contains(f.Message, "suspended it after repeated crashes") { @@ -290,8 +426,8 @@ func TestAppStoreInstallFailsForSuspendedApp(t *testing.T) { // ready) is a successful install. func TestAppStoreInstallSlowAppIsNotAFailure(t *testing.T) { shortStartWait(t, 400*time.Millisecond) - _, report, stderr, f := installWithSupervisor(t, "io.test.slow", func(appDir string) { - supLog(t, appDir, time.Now(), "supervise-start", "spawn") + _, report, stderr, f := installWithSupervisor(t, "io.test.slow", func(appDir, sha string) { + supLog(t, appDir, time.Now(), ofBinary(sha, "supervise-start"), ofBinary(sha, "spawn")) }) if f != nil { t.Fatalf("install of a slow app failed: %+v\n%s", f, stderr) @@ -353,20 +489,179 @@ func TestAppStoreInstallDoesNotWaitWhenNothingWillStartTheApp(t *testing.T) { } fast(t, report, time.Since(begin)) }) + // The supervisor orders a prerelease below its release, and refuses it. + t.Run("--force to a prerelease of the installed version", func(t *testing.T) { + const id = "io.test.prerelease" + isolateAppStoreTest(t) + installQuiet(t, writeVersionedBundle(t, id, "1.0.0", "v1"), "--local", "--no-wait") + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + bundle := writeVersionedBundle(t, id, "1.0.0-beta.1", "beta") + begin := time.Now() + var stdout string + withJSON(func() { stdout, _ = installQuiet(t, bundle, "--local", "--force") }) + var report map[string]any + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("%v\n%s", err, stdout) + } + fast(t, report, time.Since(begin)) + }) +} + +// upgradeWithSupervisor installs v1.0.0 of id without waiting, then installs +// toVersion over it with --force and a daemon socket listening, while +// supervise plays the daemon's supervisor on the app dir once the new +// install is swapped in. sha is the new binary's sha256, which the +// supervisor logs on the new instance's supervise-start and spawn. +func upgradeWithSupervisor(t *testing.T, id, toVersion string, supervise func(appDir, sha string)) (report map[string]any, stderr string, failure *trappedFatal) { + t.Helper() + root := isolateAppStoreTest(t) + installQuiet(t, writeVersionedBundle(t, id, "1.0.0", "v1"), "--local", "--no-wait") + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + bundle := writeVersionedBundle(t, id, toVersion, "v2 "+toVersion) + sha := sha256File(filepath.Join(bundle, "bin", "app")) + appDir := filepath.Join(root, id) + done := make(chan struct{}) + stop := make(chan struct{}) + go func() { + defer close(done) + for { + if m, _, err := readInstalledManifest(appDir); err == nil && m.Binary.SHA256 == sha { + break + } + select { + case <-stop: + return + case <-time.After(10 * time.Millisecond): + } + } + supervise(appDir, sha) + }() + var stdout string + withJSON(func() { + stdout, stderr, failure = runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local", "--force"}) }) + }) + close(stop) + <-done + if err := json.Unmarshal([]byte(stdout), &report); err != nil { + t.Fatalf("install report: %v\nstdout: %s\nstderr: %s", err, stdout, stderr) + } + return report, stderr, failure +} + +// After the swap, the supervisor keeps running the replaced instance until +// its next rescan. What that instance logs in the meantime (its crash loop +// ending in a suspend, or the exit it logs when the rescan stops it) is not +// the new install's. +func TestAppStoreUpgradeIgnoresTheReplacedInstance(t *testing.T) { + shortStartWait(t, 10*time.Second) + t.Run("old instance's crash loop is suspended after the swap", func(t *testing.T) { + report, stderr, f := upgradeWithSupervisor(t, "io.test.oldcrashloop", "2.0.0", func(appDir, sha string) { + // The old instance's sixth exit in a minute, after the swap. + supLog(t, appDir, time.Now(), ofBinary(testOldSHA, "spawn"), `exit "exit_code":1`, `suspend "reason":">5 crashes in 1m0s"`) + touch(t, filepath.Join(appDir, ".suspended")) + time.Sleep(50 * time.Millisecond) // the rescan + supLog(t, appDir, time.Now(), ofBinary(sha, "upgrade-applied"), ofBinary(sha, "supervise-start")) + _ = os.Remove(filepath.Join(appDir, ".suspended")) // supervise-start clears it + supLog(t, appDir, time.Now(), ofBinary(sha, "spawn")) + touch(t, filepath.Join(appDir, "app.sock")) + }) + if f != nil { + t.Fatalf("a good upgrade failed: %+v\nstderr: %s", f, stderr) + } + if report["start_state"] != appStartStarted { + t.Fatalf("report = %v", report) + } + if _, has := report["start_exits"]; has { + t.Errorf("the old instance's exit was counted: %v", report) + } + }) + t.Run("old instance stopped by the rescan", func(t *testing.T) { + report, stderr, f := upgradeWithSupervisor(t, "io.test.oldstopped", "2.0.0", func(appDir, sha string) { + // The new instance's supervise-start is logged before the old + // instance has exited: the old one gets up to 3s to shut down. + supLog(t, appDir, time.Now(), ofBinary(sha, "upgrade-applied"), ofBinary(sha, "supervise-start"), + `exit "exit_code":-1`, `supervise-stop "reason":"context canceled"`, ofBinary(sha, "spawn")) + touch(t, filepath.Join(appDir, "app.sock")) + }) + if f != nil { + t.Fatalf("%+v\nstderr: %s", f, stderr) + } + if report["start_state"] != appStartStarted { + t.Fatalf("report = %v", report) + } + if _, has := report["start_exits"]; has { + t.Errorf("the old instance's exit was counted: %v", report) + } + }) + t.Run("new instance crashes after the old one is stopped", func(t *testing.T) { + report, stderr, f := upgradeWithSupervisor(t, "io.test.newcrashes", "2.0.0", func(appDir, sha string) { + supLog(t, appDir, time.Now(), ofBinary(sha, "upgrade-applied"), `exit "exit_code":-1`, ofBinary(sha, "supervise-start"), + ofBinary(sha, "spawn"), `exit "exit_code":4`) + time.Sleep(100 * time.Millisecond) // the supervisor's restart delay + supLog(t, appDir, time.Now(), ofBinary(sha, "spawn"), `exit "exit_code":4`) + }) + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("install = %+v, want app_start_failed\nstderr: %s", f, stderr) + } + if report["start_exits"] != float64(2) || !strings.Contains(f.Message, "exited 2 times at start (last exit code 4)") { + t.Errorf("exits miscounted: %v\n%s", report, f.Message) + } + }) +} + +// The supervisor refuses an install it orders below the version it runs, +// and logs downgrade-refused on every rescan. That is the outcome: the new +// version will not start, so install says so at once instead of waiting. +func TestAppStoreInstallReportsDowngradeRefusal(t *testing.T) { + shortStartWait(t, 10*time.Second) + begin := time.Now() + // v1.0.0 is on disk, but the daemon runs v2.0.0 (it refused v1.0.0 + // earlier), so it refuses v1.5.0 too. + report, stderr, f := upgradeWithSupervisor(t, "io.test.refused", "1.5.0", func(appDir, _ string) { + supLog(t, appDir, time.Now(), `downgrade-refused "reason":"rescan: refusing 1.5.0 (existing 2.0.0)"`) + }) + if took := time.Since(begin); took > 5*time.Second { + t.Errorf("install waited %s for an app the daemon refused", took) + } + if f == nil || f.Code != "app_start_failed" { + t.Fatalf("install = %+v, want app_start_failed\nreport: %v\nstderr: %s", f, report, stderr) + } + if !strings.Contains(f.Message, "refusing 1.5.0 (existing 2.0.0)") || !strings.Contains(f.Message, "older") { + t.Errorf("message = %q", f.Message) + } + if !strings.Contains(stderr, "restart") || report["start_state"] != appStartFailed { + t.Errorf("report = %v\nstderr: %s", report, stderr) + } } // Human output: the start is reported in place of "will be picked up within // ~30s", and a failed start still prints what was installed first. func TestAppStoreInstallTextOutputReportsStart(t *testing.T) { shortStartWait(t, 10*time.Second) + // events are logged once the install is there; supervise-start and spawn + // as the new install's, and a final spawn opens the app's socket. run := func(t *testing.T, id string, events ...string) (stdout, stderr string, f *trappedFatal) { root := isolateAppStoreTest(t) t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + bundle := writeVersionedBundle(t, id, "1.0.0", "v1") + sha := sha256File(filepath.Join(bundle, "bin", "app")) appDir := filepath.Join(root, id) + done := make(chan struct{}) go func() { + defer close(done) + if len(events) == 0 { + return + } for i := 0; i < 500; i++ { if _, err := os.Stat(filepath.Join(appDir, "manifest.json")); err == nil { - supLog(t, appDir, time.Now(), events...) + var lines []string + for _, ev := range events { + if ev == "supervise-start" || ev == "spawn" { + ev = ofBinary(sha, ev) + } + lines = append(lines, ev) + } + supLog(t, appDir, time.Now(), lines...) if events[len(events)-1] == "spawn" { touch(t, filepath.Join(appDir, "app.sock")) } @@ -375,8 +670,9 @@ func TestAppStoreInstallTextOutputReportsStart(t *testing.T) { time.Sleep(10 * time.Millisecond) } }() - bundle := writeVersionedBundle(t, id, "1.0.0", "v1") - return runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local"}) }) + stdout, stderr, f = runTrapped(t, func() { cmdAppStoreInstall([]string{bundle, "--local"}) }) + <-done + return stdout, stderr, f } t.Run("started", func(t *testing.T) { stdout, stderr, f := run(t, "io.test.textok", "supervise-start", "spawn") @@ -402,4 +698,66 @@ func TestAppStoreInstallTextOutputReportsStart(t *testing.T) { t.Errorf("stderr:\n%s", stderr) } }) + // One note, not "has not started after 300ms" and "will be picked up + // within ~30s" both. + t.Run("not picked up by the end of the wait", func(t *testing.T) { + shortStartWait(t, 300*time.Millisecond) + stdout, stderr, f := run(t, "io.test.textnotyet") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + if !strings.Contains(stdout, "has not started io.test.textnotyet") || strings.Contains(stdout, "within ~30s") { + t.Errorf("stdout:\n%s", stdout) + } + }) + t.Run("an older version is not waited for, and says so", func(t *testing.T) { + const id = "io.test.textolder" + isolateAppStoreTest(t) + installQuiet(t, writeVersionedBundle(t, id, "1.0.0", "v1"), "--local", "--no-wait") + t.Setenv("PILOT_SOCKET", newStreamDaemon(t).path) + stdout, stderr := installQuiet(t, writeVersionedBundle(t, id, "1.0.0-rc.1", "rc"), "--local", "--force") + if !strings.Contains(stdout, "v1.0.0-rc.1 is older than the v1.0.0 it replaced") || strings.Contains(stdout, "within ~30s") { + t.Errorf("stdout:\n%s", stdout) + } + if strings.Contains(stderr, "waiting up to") { + t.Errorf("stderr:\n%s", stderr) + } + }) +} + +// --wait replaces the default wait; 0 does not wait. +func TestAppStoreInstallWaitFlag(t *testing.T) { + shortStartWait(t, 30*time.Second) // the default, which --wait replaces + slow := func(appDir, sha string) { + supLog(t, appDir, time.Now(), ofBinary(sha, "supervise-start"), ofBinary(sha, "spawn")) + } + t.Run("--wait 300ms", func(t *testing.T) { + _, report, stderr, f := installWithSupervisor(t, "io.test.waitshort", slow, "--wait", "300ms") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + if ms, _ := report["start_waited_ms"].(float64); report["start_state"] != appStartStarting || ms < 300 || ms > 5000 { + t.Errorf("report = %v", report) + } + }) + t.Run("--wait 0", func(t *testing.T) { + _, report, stderr, f := installWithSupervisor(t, "io.test.waitzero", slow, "--wait", "0") + if f != nil { + t.Fatalf("%+v\n%s", f, stderr) + } + if _, has := report["start_state"]; has { + t.Errorf("waited: %v", report) + } + }) + t.Run("invalid", func(t *testing.T) { + isolateAppStoreTest(t) + for _, bad := range [][]string{{"--wait"}, {"--wait", "soon"}, {"--wait", "-1s"}} { + _, _, f := runTrapped(t, func() { + cmdAppStoreInstall(append([]string{writeVersionedBundle(t, "io.test.waitbad", "1.0.0", "v1"), "--local"}, bad...)) + }) + if f == nil || f.Code != "invalid_argument" { + t.Errorf("%v: %+v", bad, f) + } + } + }) } diff --git a/docs/cli-reference.md b/docs/cli-reference.md index 6fd73958..0078e0c8 100644 --- a/docs/cli-reference.md +++ b/docs/cli-reference.md @@ -90,7 +90,9 @@ Agent tool discovery: App store (install + call local capability apps; full help: pilotctl appstore help): pilotctl appstore catalogue list apps available for one-command install pilotctl appstore view [--all-changelog] app detail page (description, methods, permissions) - pilotctl appstore install [--force] install by catalogue ID (fetch + verify + extract) + pilotctl appstore install [--force] [--no-wait | --wait ] + install by catalogue ID (fetch + verify + extract) + and wait up to 20s for the app's first start pilotctl appstore list list installed apps + their IPC methods pilotctl appstore call [json-args] dispatch an IPC call into an app pilotctl appstore status|caps|audit|restart|uninstall From 63c982aa40e595e22f0ac14fda3058c6ade8d6f6 Mon Sep 17 00:00:00 2001 From: Teo Calin Date: Wed, 7 Oct 2026 17:10:16 +0300 Subject: [PATCH 3/3] appstore: start counts begin again at the new instance's supervise-start Review fix. With a binary identical across versions (a manifest-only bump) the old instance's restarts after the swap log the new manifest's sha, so they were counted, and two old crashes could report the new install as failed. The counts now restart at the new instance's supervise-start. Co-Authored-By: Claude Opus 5.5 --- cmd/pilotctl/appstore_startwait.go | 8 +++++++- cmd/pilotctl/zz_appstore_startwait_test.go | 7 +++++++ 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/cmd/pilotctl/appstore_startwait.go b/cmd/pilotctl/appstore_startwait.go index ef23fbfe..64675f25 100644 --- a/cmd/pilotctl/appstore_startwait.go +++ b/cmd/pilotctl/appstore_startwait.go @@ -48,7 +48,9 @@ import ( // instance's supervise-start and spawn carry the sha256 of the binary it // runs, which is the installed manifest's. So nothing counts before one of // those; an exit counts only when it ends a start attempt of the new -// instance; and a suspend only when it follows one of its exits. +// instance; and a suspend only when it follows one of its exits. When the +// binary is identical across versions the old instance's restarts carry the +// same sha, so the counts start again at the new instance's supervise-start. // appStartWait is how long install waits for the app's first start unless // --wait says otherwise. appStartPoll is how often it looks. Vars so tests @@ -157,8 +159,12 @@ func readAppStart(tg appStartTarget) appStartStatus { if !thisBinary { continue } + // The new instance starts here: anything counted so far was + // the old instance's (a manifest-only bump runs an identical + // binary, so its restarts log this sha too). ours, attempt, ended, noProcess = true, false, false, false st.Refusal = "" + st.Spawns, st.Exits, st.ExitCode, st.StartError, st.Suspended = 0, 0, 0, "", false case "spawn": if !thisBinary { continue // the old instance, restarting before the rescan replaced it diff --git a/cmd/pilotctl/zz_appstore_startwait_test.go b/cmd/pilotctl/zz_appstore_startwait_test.go index e44e67ea..0a1d449d 100644 --- a/cmd/pilotctl/zz_appstore_startwait_test.go +++ b/cmd/pilotctl/zz_appstore_startwait_test.go @@ -89,6 +89,13 @@ func TestReadAppStart(t *testing.T) { t.Errorf("pilotctl's install line counted as a supervisor event: %+v", st) } }}, + {name: "identical binary: the old instance's crashes before the new supervise-start do not count", setup: func(t *testing.T, dir string) { + supLog(t, dir, after, spawn, exit1, spawn, exit1, start, spawn) + }, want: appStartStarting, check: func(t *testing.T, st appStartStatus) { + if st.Exits != 0 || st.Spawns != 1 { + t.Errorf("counts carried over from the old instance: spawns %d, exits %d", st.Spawns, st.Exits) + } + }}, {name: "spawned, socket not there yet", setup: func(t *testing.T, dir string) { supLog(t, dir, after, start, spawn) }, want: appStartStarting},