From 328bad9053b16cca58faa740600dcbca9a1844ed Mon Sep 17 00:00:00 2001 From: Teo Calin Date: Thu, 8 Oct 2026 14:04:37 +0300 Subject: [PATCH 1/2] appstore: messages carry a level, and a skipped dir is logged once Seen on a Mac: the daemon's log held 1,574 copies of "appstore skip io.pilot.wallet: read manifest: open .../manifest.json: no such file or directory" in under an hour. The wallet binary, run outside the daemon, keeps its EVM identity in ~/.pilot/apps/io.pilot.wallet, a dir with no manifest, and the rescan (every 2 s) logged it every time. The Mac app counted these, and the app store's routine "starting" line, as repeated warnings: the app store logs through the log package, so none of its lines has a level. - Every reason a scan skips a dir is logged once, and again only when the reason changes or the dir comes back. A dir with no manifest.json says it is not an installed app and is left alone (INFO). - Config.Slog, when set, receives the messages with a level: INFO for routine ones, WARN for problems (crash loops and suspensions, failed verification, a manifest that does not parse or verify, refused downgrades, audit-log errors, a socket that never appears). Without it the output is unchanged. Co-Authored-By: Claude Opus 5.5 --- plugin/appstore/logging.go | 42 +++++ plugin/appstore/reap.go | 2 +- plugin/appstore/rlimit_linux.go | 5 +- plugin/appstore/rlimit_linux_test.go | 4 +- plugin/appstore/rlimit_other.go | 5 +- plugin/appstore/rlimit_other_test.go | 2 +- plugin/appstore/service.go | 23 ++- plugin/appstore/supervisor.go | 152 ++++++++++-------- .../appstore/zz2_supervisor_lifecycle_test.go | 2 +- plugin/appstore/zz9_quiet_skips_test.go | 113 +++++++++++++ 10 files changed, 268 insertions(+), 82 deletions(-) create mode 100644 plugin/appstore/logging.go create mode 100644 plugin/appstore/zz9_quiet_skips_test.go diff --git a/plugin/appstore/logging.go b/plugin/appstore/logging.go new file mode 100644 index 0000000..15093b6 --- /dev/null +++ b/plugin/appstore/logging.go @@ -0,0 +1,42 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package appstore + +import ( + "context" + "fmt" + "log" + "log/slog" +) + +// appLogger carries the app store's messages with a level: Printf for +// routine ones, Warnf for problems an operator may need to act on. With +// Config.Slog set they go to that logger (the daemon's log, where a reader +// tells problems from routine by level); otherwise to the *log.Logger as +// before, which has no levels. +type appLogger struct { + std *log.Logger + sl *slog.Logger +} + +func newAppLogger(std *log.Logger, sl *slog.Logger) *appLogger { + return &appLogger{std: std, sl: sl} +} + +// Printf logs a routine message (INFO). +func (l *appLogger) Printf(format string, args ...any) { + l.logf(slog.LevelInfo, format, args...) +} + +// Warnf logs a problem (WARN). +func (l *appLogger) Warnf(format string, args ...any) { + l.logf(slog.LevelWarn, format, args...) +} + +func (l *appLogger) logf(level slog.Level, format string, args ...any) { + if l.sl != nil { + l.sl.Log(context.Background(), level, "appstore: "+fmt.Sprintf(format, args...)) + return + } + l.std.Printf(format, args...) +} diff --git a/plugin/appstore/reap.go b/plugin/appstore/reap.go index cb9ad2a..c35d469 100644 --- a/plugin/appstore/reap.go +++ b/plugin/appstore/reap.go @@ -193,7 +193,7 @@ func (s *supervisor) watchSocket(ctx context.Context, a *installedApp, pid int, case err == nil: seen = true case seen && os.IsNotExist(err): - s.logger.Printf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid) + s.logger.Warnf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid) s.writeAuditLine(a, auditEvent{Event: "socket-lost", PID: pid}) if syscall.Kill(-pid, syscall.SIGTERM) != nil { _ = syscall.Kill(pid, syscall.SIGTERM) diff --git a/plugin/appstore/rlimit_linux.go b/plugin/appstore/rlimit_linux.go index 66100b9..27b6235 100644 --- a/plugin/appstore/rlimit_linux.go +++ b/plugin/appstore/rlimit_linux.go @@ -3,7 +3,6 @@ package appstore import ( - "log" "syscall" "unsafe" ) @@ -44,7 +43,7 @@ type rlimit64 struct { // There is a tiny race: between cmd.Start and prlimit landing, the // child can allocate. For an app starting from a clean state that's a // handful of fds / a small allocation — well under the caps. -func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger) { +func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *appLogger) { setLimit := func(resource int, name string, val uint64) { want := rlimit64{Cur: val, Max: val} // SYS_PRLIMIT64 takes (pid, resource, *new_limit, *old_limit). @@ -57,7 +56,7 @@ func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger 0, 0, 0, ) if errno != 0 { - logger.Printf("prlimit pid=%d %s=%d: %v (proceeding; OS-wide ulimit still applies)", pid, name, val, errno) + logger.Warnf("prlimit pid=%d %s=%d: %v (proceeding; OS-wide ulimit still applies)", pid, name, val, errno) return } logger.Printf("prlimit pid=%d %s=%d ok", pid, name, val) diff --git a/plugin/appstore/rlimit_linux_test.go b/plugin/appstore/rlimit_linux_test.go index 66de634..7ea51b8 100644 --- a/plugin/appstore/rlimit_linux_test.go +++ b/plugin/appstore/rlimit_linux_test.go @@ -43,7 +43,7 @@ func TestApplyChildResourceLimits_SetsAddressSpace(t *testing.T) { cmd := startSleeper(t) pid := cmd.Process.Pid const limit uint64 = 2 << 30 - applyChildResourceLimits(pid, limit, newQuietLogger(t)) + applyChildResourceLimits(pid, limit, newAppLogger(newQuietLogger(t), nil)) if got := getChildRlimit(t, pid, syscall.RLIMIT_AS); got.Cur != limit { t.Errorf("RLIMIT_AS Cur = %d, want %d", got.Cur, limit) @@ -59,7 +59,7 @@ func TestApplyChildResourceLimits_ZeroSkipsAddressSpace(t *testing.T) { cmd := startSleeper(t) pid := cmd.Process.Pid before := getChildRlimit(t, pid, syscall.RLIMIT_AS) - applyChildResourceLimits(pid, 0, newQuietLogger(t)) + applyChildResourceLimits(pid, 0, newAppLogger(newQuietLogger(t), nil)) after := getChildRlimit(t, pid, syscall.RLIMIT_AS) if after.Cur != before.Cur { t.Errorf("RLIMIT_AS changed despite zero limit: before=%d after=%d", before.Cur, after.Cur) diff --git a/plugin/appstore/rlimit_other.go b/plugin/appstore/rlimit_other.go index 23738f6..975958b 100644 --- a/plugin/appstore/rlimit_other.go +++ b/plugin/appstore/rlimit_other.go @@ -3,7 +3,6 @@ package appstore import ( - "log" "sync" ) @@ -18,8 +17,8 @@ var resourceLimitWarning sync.Once // // The addrSpaceLimit parameter is accepted for signature parity with the // Linux build and ignored here. -func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger) { +func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *appLogger) { resourceLimitWarning.Do(func() { - logger.Print("resource limits not enforced on this platform (linux-only); child file-descriptor and address-space caps are ignored") + logger.Printf("resource limits not enforced on this platform (linux-only); child file-descriptor and address-space caps are ignored") }) } diff --git a/plugin/appstore/rlimit_other_test.go b/plugin/appstore/rlimit_other_test.go index 085c596..df84316 100644 --- a/plugin/appstore/rlimit_other_test.go +++ b/plugin/appstore/rlimit_other_test.go @@ -17,7 +17,7 @@ func TestResourceLimitWarningOnce(t *testing.T) { var wg sync.WaitGroup for i := 0; i < 20; i++ { wg.Add(1) - go func(pid int) { defer wg.Done(); applyChildResourceLimits(pid, 4<<30, logger) }(i) + go func(pid int) { defer wg.Done(); applyChildResourceLimits(pid, 4<<30, newAppLogger(logger, nil)) }(i) } wg.Wait() if got := strings.Count(output.String(), "resource limits not enforced"); got != 1 { diff --git a/plugin/appstore/service.go b/plugin/appstore/service.go index 62cf3bf..1b93a5c 100644 --- a/plugin/appstore/service.go +++ b/plugin/appstore/service.go @@ -15,6 +15,7 @@ import ( "errors" "fmt" "log" + "log/slog" "os" "path/filepath" "sync" @@ -54,6 +55,12 @@ type Config struct { // service logs via the standard log package. Logger *log.Logger + // Slog, when set, receives the messages instead of Logger, with a + // level: INFO for routine ones, WARN for problems an operator may need + // to act on. The daemon passes its own logger, so these lines read and + // filter like the rest of its log. + Slog *slog.Logger + // RescanInterval controls how often the supervisor re-walks // InstallRoot looking for newly-landed apps (e.g. dropped by // `pilotctl appstore install` while the daemon is running). @@ -106,7 +113,7 @@ func catalogPubkeyIsPlaceholder(pk []byte) bool { // Service implements coreapi.Service for the app store. type Service struct { cfg Config - logger *log.Logger + logger *appLogger sup *supervisor // started in Start; nil before then cancel context.CancelFunc doneCh chan struct{} @@ -125,11 +132,11 @@ func NewService(cfg Config) *Service { if cfg.CatalogPubkey == nil { cfg.CatalogPubkey = EmbeddedCatalogPubkey } - logger := cfg.Logger - if logger == nil { - logger = log.New(os.Stderr, "appstore ", log.LstdFlags|log.Lmicroseconds) + std := cfg.Logger + if std == nil { + std = log.New(os.Stderr, "appstore ", log.LstdFlags|log.Lmicroseconds) } - return &Service{cfg: cfg, logger: logger} + return &Service{cfg: cfg, logger: newAppLogger(std, cfg.Slog)} } // Name returns the plugin identifier reported to the runtime registry. @@ -187,14 +194,14 @@ func (s *Service) Start(ctx context.Context, deps Deps) error { // operator catch a misbuilt release before any user-visible // install completes. if catalogPubkeyIsPlaceholder(s.cfg.CatalogPubkey) { - s.logger.Printf("WARNING: dev-mode trust anchor — CatalogPubkey is the all-zeros placeholder; signed catalogs will NOT verify. Replace EmbeddedCatalogPubkey for production builds.") + s.logger.Warnf("WARNING: dev-mode trust anchor — CatalogPubkey is the all-zeros placeholder; signed catalogs will NOT verify. Replace EmbeddedCatalogPubkey for production builds.") } runCtx, cancel := context.WithCancel(ctx) s.cancel = cancel s.doneCh = make(chan struct{}) - s.sup = newSupervisor(s.cfg, deps, s.logger) + s.sup = newSupervisor(s.cfg, deps, s.logger.std) apps, err := s.sup.scanInstalled() if err != nil { cancel() @@ -227,7 +234,7 @@ func (s *Service) Stop(ctx context.Context) error { s.sup = nil return nil case <-ctx.Done(): - s.logger.Printf("stop: ctx deadline reached before drain") + s.logger.Warnf("stop: ctx deadline reached before drain") return ctx.Err() } } diff --git a/plugin/appstore/supervisor.go b/plugin/appstore/supervisor.go index 64c99df..8bb67c8 100644 --- a/plugin/appstore/supervisor.go +++ b/plugin/appstore/supervisor.go @@ -8,6 +8,7 @@ import ( "errors" "fmt" "io" + "io/fs" "log" "net" "os" @@ -87,12 +88,12 @@ func (s *supervisor) writeAuditLine(a *installedApp, ev auditEvent) { s.rotateAuditIfLarge(a.Dir) f, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) if err != nil { - s.logger.Printf("audit open %s: %v", path, err) + s.logger.Warnf("audit open %s: %v", path, err) return } defer f.Close() if _, err := f.Write(body); err != nil { - s.logger.Printf("audit write %s: %v", path, err) + s.logger.Warnf("audit write %s: %v", path, err) } } @@ -141,7 +142,7 @@ func (s *supervisor) rotateGenerations(appDir string, keep int) { } // Discard the generation that would fall off the end. if err := os.Remove(gen(keep)); err != nil && !errors.Is(err, os.ErrNotExist) { - s.logger.Printf("audit rotate: remove %s: %v", gen(keep), err) + s.logger.Warnf("audit rotate: remove %s: %v", gen(keep), err) } // Shift each surviving generation down one slot, oldest first so we // never clobber a file we still need to move. @@ -151,7 +152,7 @@ func (s *supervisor) rotateGenerations(appDir string, keep int) { continue // gap in the chain — nothing to move } if err := os.Rename(src, dst); err != nil { - s.logger.Printf("audit rotate %s → %s: %v", src, dst, err) + s.logger.Warnf("audit rotate %s → %s: %v", src, dst, err) } } } @@ -162,7 +163,7 @@ func (s *supervisor) rotateGenerations(appDir string, keep int) { type supervisor struct { cfg Config deps Deps - logger *log.Logger + logger *appLogger // mu guards installed + ready + crashes + appCancel. mu sync.RWMutex @@ -174,9 +175,9 @@ type supervisor struct { // sigMu guards sigFails and misnamed. Kept separate from mu because // this bookkeeping happens inside scanInstalled, which must not hold // the main lock while walking the filesystem. - sigMu sync.Mutex - sigFails map[string]*sigFailRecord // install-dir name → manifest-signature failure state - misnamed map[string]bool // install-dir names skipped (and logged) because they are not their manifest's app ID + sigMu sync.Mutex + sigFails map[string]*sigFailRecord // install-dir name → manifest-signature failure state + skipLogged map[string]string // install-dir name → the skip line last logged for it (noteSkipped) } func newSupervisor(cfg Config, deps Deps, logger *log.Logger) *supervisor { @@ -185,15 +186,15 @@ func newSupervisor(cfg Config, deps Deps, logger *log.Logger) *supervisor { deps.Telemetry = noopEmitter{} } return &supervisor{ - cfg: cfg, - deps: deps, - logger: logger, - installed: map[string]*installedApp{}, - ready: map[string]bool{}, - crashes: map[string]*crashRecord{}, - appCancel: map[string]context.CancelFunc{}, - sigFails: map[string]*sigFailRecord{}, - misnamed: map[string]bool{}, + cfg: cfg, + deps: deps, + logger: newAppLogger(logger, cfg.Slog), + installed: map[string]*installedApp{}, + ready: map[string]bool{}, + crashes: map[string]*crashRecord{}, + appCancel: map[string]context.CancelFunc{}, + sigFails: map[string]*sigFailRecord{}, + skipLogged: map[string]string{}, } } @@ -381,10 +382,10 @@ func (s *supervisor) noteSignatureFailure(dirName, appID, hash string, verr erro s.sigMu.Unlock() if firstForHash { - s.logger.Printf("app=%s (%s): manifest signature verification failed: %v — deduping identical failures, retrying with backoff", appID, dirName, verr) + s.logger.Warnf("app=%s (%s): manifest signature verification failed: %v — deduping identical failures, retrying with backoff", appID, dirName, verr) } if emitQuarantine { - s.logger.Printf("app=%s (%s): quarantined after %d consecutive signature failures for manifest %s — retrying only on slow backoff until the manifest changes or is re-installed", appID, dirName, failsN, hash[:12]) + s.logger.Warnf("app=%s (%s): quarantined after %d consecutive signature failures for manifest %s — retrying only on slow backoff until the manifest changes or is re-installed", appID, dirName, failsN, hash[:12]) } } @@ -402,39 +403,54 @@ func (s *supervisor) clearSignatureFailure(dirName, appID string) { } } -// noteMisnamed logs the install dirs one scan skipped because their name is -// not their manifest's app ID (skipped maps dir name → app ID; present holds -// every dir name in the scan). Each dir is logged once, not on every rescan -// tick; a name absent from this scan is forgotten, so a dir that comes back -// later (the next install's staging dir) is logged again. -// -// An .previous with no beside it is an install interrupted mid-swap: -// the app is no longer running, so that line says how to restore it. -func (s *supervisor) noteMisnamed(skipped map[string]string, present map[string]bool) { +// skipNote is why one scan skipped an install-root dir: the line to log +// and whether it is a problem (WARN) or routine (INFO). +type skipNote struct { + msg string + warn bool +} + +// noteSkipped logs the install-root dirs one scan skipped (keyed by dir +// name). The rescan runs every few seconds, so each dir is logged once, and +// again only when its reason changes; a name absent from this scan is +// forgotten, so a dir that comes back later (the next install's staging +// dir) is logged again. Logging every tick filled the daemon's log: a dir +// holding only an app's state was logged 1,574 times in under an hour. +func (s *supervisor) noteSkipped(skipped map[string]skipNote) { s.sigMu.Lock() var fresh []string - for name := range skipped { - if !s.misnamed[name] { + for name, n := range skipped { + if s.skipLogged[name] != n.msg { fresh = append(fresh, name) } } - s.misnamed = make(map[string]bool, len(skipped)) - for name := range skipped { - s.misnamed[name] = true + s.skipLogged = make(map[string]string, len(skipped)) + for name, n := range skipped { + s.skipLogged[name] = n.msg } s.sigMu.Unlock() sort.Strings(fresh) for _, name := range fresh { - id := skipped[name] - if strings.HasPrefix(name, id+".previous") && !present[id] { - s.logger.Printf("skip %s: app %s is not installed, and this is its previous install, left by an install that did not finish — run `pilotctl appstore install %s` to restore it", name, id, id) - continue + if n := skipped[name]; n.warn { + s.logger.Warnf("%s", n.msg) + } else { + s.logger.Printf("%s", n.msg) } - s.logger.Printf("skip %s: dir name is not its app id %s (an install's staging or replaced dir) — not adopting", name, id) } } +// misnamedNote is the skip note for a dir holding a valid manifest for app +// id under another name (present holds every dir name in the scan). An +// .previous with no beside it is an install interrupted mid-swap: +// the app is no longer running, so that note says how to restore it. +func misnamedNote(name, id string, present map[string]bool) skipNote { + if strings.HasPrefix(name, id+".previous") && !present[id] { + return skipNote{warn: true, msg: fmt.Sprintf("skip %s: app %s is not installed, and this is its previous install, left by an install that did not finish — run `pilotctl appstore install %s` to restore it", name, id, id)} + } + return skipNote{msg: fmt.Sprintf("skip %s: dir name is not its app id %s (an install's staging or replaced dir) — not adopting", name, id)} +} + // scanInstalled walks InstallRoot, reads each `/manifest.json`, and // returns the verified-by-syntax set. Sha256 verification is per-launch // (in run()), not per-scan, so a corrupted binary surfaces at the right @@ -451,7 +467,8 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { return nil, err } var out []*installedApp - misnamed := map[string]string{} // dir name → app ID, for noteMisnamed + skipped := map[string]skipNote{} // dir name → why it was skipped, for noteSkipped + misnamed := map[string]string{} // dir name → app ID for _, e := range entries { if !e.IsDir() { continue @@ -459,17 +476,23 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { dir := filepath.Join(s.cfg.InstallRoot, e.Name()) mfPath := filepath.Join(dir, "manifest.json") data, err := os.ReadFile(mfPath) + if errors.Is(err, fs.ErrNotExist) { + // Not an install: an app run outside the daemon can keep its + // state under its id here (the wallet's identity-evm.json). + skipped[e.Name()] = skipNote{msg: fmt.Sprintf("skip %s: no manifest.json — not an installed app; left alone", e.Name())} + continue + } if err != nil { - s.logger.Printf("skip %s: read manifest: %v", e.Name(), err) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: read manifest: %v", e.Name(), err)} continue } m, err := manifest.Parse(data) if err != nil { - s.logger.Printf("skip %s: parse: %v", e.Name(), err) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: parse: %v", e.Name(), err)} continue } if errs := m.Validate(); len(errs) != 0 { - s.logger.Printf("skip %s: invalid manifest: %v", e.Name(), errs[0]) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: invalid manifest: %v", e.Name(), errs[0])} continue } // Only / is an install. pilotctl's install leaves @@ -494,7 +517,7 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { sideloaded := sideErr == nil if sideloaded { if err := manifest.EnforceSideloadPolicy(m); err != nil { - s.logger.Printf("skip %s: sideload policy violation: %v", e.Name(), err) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: sideload policy violation: %v", e.Name(), err)} continue } } else { @@ -541,7 +564,7 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { // binaries under the daemon's uid. binaryPath, err := resolveUnder(dir, m.Binary.Path) if err != nil { - s.logger.Printf("skip %s: binary path %q escapes app dir: %v", e.Name(), m.Binary.Path, err) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: binary path %q escapes app dir: %v", e.Name(), m.Binary.Path, err)} continue } // Reject symlinks on the resolved binary. An attacker with @@ -552,7 +575,7 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { // right error when it tries to exec. We only refuse a path // that EXISTS AS A SYMLINK. if fi, err := os.Lstat(binaryPath); err == nil && fi.Mode()&os.ModeSymlink != 0 { - s.logger.Printf("skip %s: binary path %s is a symlink (refusing)", e.Name(), binaryPath) + skipped[e.Name()] = skipNote{warn: true, msg: fmt.Sprintf("skip %s: binary path %s is a symlink (refusing)", e.Name(), binaryPath)} continue } out = append(out, &installedApp{ @@ -569,7 +592,10 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { for _, e := range entries { present[e.Name()] = true } - s.noteMisnamed(misnamed, present) + for name, id := range misnamed { + skipped[name] = misnamedNote(name, id, present) + } + s.noteSkipped(skipped) return out, nil } @@ -588,7 +614,7 @@ func (s *supervisor) registerInstalled(apps []*installedApp) { for _, a := range apps { if existing, ok := s.installed[a.Manifest.ID]; ok { if compareVersions(a.Manifest.AppVersion, existing.Manifest.AppVersion) < 0 { - s.logger.Printf("downgrade refused: app=%s new=%s old=%s — keeping existing version", + s.logger.Warnf("downgrade refused: app=%s new=%s old=%s — keeping existing version", a.Manifest.ID, a.Manifest.AppVersion, existing.Manifest.AppVersion) s.writeAuditLine(a, auditEvent{Event: "downgrade-refused", Reason: fmt.Sprintf("refusing %s (existing %s)", a.Manifest.AppVersion, existing.Manifest.AppVersion)}) @@ -677,7 +703,7 @@ func (s *supervisor) run(ctx context.Context, apps []*installedApp) { func (s *supervisor) rescanForNew() []*installedApp { apps, err := s.scanInstalled() if err != nil { - s.logger.Printf("rescan: %v", err) + s.logger.Warnf("rescan: %v", err) return nil } s.mu.Lock() @@ -701,7 +727,7 @@ func (s *supervisor) rescanForNew() []*installedApp { delete(s.ready, a.Manifest.ID) delete(s.crashes, a.Manifest.ID) if err := os.Remove(filepath.Join(a.Dir, suspendedMarkerName)); err != nil && !errors.Is(err, os.ErrNotExist) { - s.logger.Printf("rescan: app id=%s: remove suspended marker: %v", a.Manifest.ID, err) + s.logger.Warnf("rescan: app id=%s: remove suspended marker: %v", a.Manifest.ID, err) } s.logger.Printf("rescan: rebuilt bundle detected: app=%s %s binary %s → %s — restarting", a.Manifest.ID, a.Manifest.AppVersion, shortSHA(existing.Manifest.Binary.SHA256), shortSHA(a.Manifest.Binary.SHA256)) @@ -716,7 +742,7 @@ func (s *supervisor) rescanForNew() []*installedApp { continue } if compareVersions(a.Manifest.AppVersion, existing.Manifest.AppVersion) < 0 { - s.logger.Printf("rescan: downgrade refused: app=%s new=%s old=%s — keeping existing version", + s.logger.Warnf("rescan: downgrade refused: app=%s new=%s old=%s — keeping existing version", a.Manifest.ID, a.Manifest.AppVersion, existing.Manifest.AppVersion) s.writeAuditLine(a, auditEvent{Event: "downgrade-refused", Reason: fmt.Sprintf("rescan: refusing %s (existing %s)", a.Manifest.AppVersion, existing.Manifest.AppVersion)}) @@ -827,7 +853,7 @@ func (s *supervisor) rescanForResume() []*installedApp { } // Consume the marker first so a partial failure doesn't loop. if err := os.Remove(markerPath); err != nil { - s.logger.Printf("rescan: app id=%s: remove resume marker: %v", id, err) + s.logger.Warnf("rescan: app id=%s: remove resume marker: %v", id, err) continue } // Clear the crash record so the new supervise goroutine @@ -841,7 +867,7 @@ func (s *supervisor) rescanForResume() []*installedApp { // Ignore "not exist" — could happen if the operator dropped // .resume before the supervisor finished writing .suspended. if err := os.Remove(filepath.Join(a.Dir, suspendedMarkerName)); err != nil && !errors.Is(err, os.ErrNotExist) { - s.logger.Printf("rescan: app id=%s: remove suspended marker: %v", id, err) + s.logger.Warnf("rescan: app id=%s: remove suspended marker: %v", id, err) } s.writeAuditLine(a, auditEvent{Event: "resume", Reason: "operator requested via .resume marker"}) s.logger.Printf("rescan: app id=%s resumed by operator request", id) @@ -955,7 +981,7 @@ func (s *supervisor) superviseOne(ctx context.Context, a *installedApp) { // Either way, the invariant after this point is: supervise goroutine // is live iff .suspended is absent. if err := os.Remove(filepath.Join(a.Dir, suspendedMarkerName)); err != nil && !errors.Is(err, os.ErrNotExist) { - s.logger.Printf("app=%s: clear stale suspended marker: %v", a.Manifest.ID, err) + s.logger.Warnf("app=%s: clear stale suspended marker: %v", a.Manifest.ID, err) } defer func() { reason := "context canceled" @@ -986,14 +1012,14 @@ func (s *supervisor) superviseOne(ctx context.Context, a *installedApp) { } if err := s.verifyBinary(a); err != nil { verifyFails++ - s.logger.Printf("app=%s: verify: %v — refusing to spawn (fail %d/%d)", a.Manifest.ID, err, verifyFails, maxVerifyFails) + s.logger.Warnf("app=%s: verify: %v — refusing to spawn (fail %d/%d)", a.Manifest.ID, err, verifyFails, maxVerifyFails) s.writeAuditLine(a, auditEvent{Event: "verify-fail", Reason: err.Error(), SHA256: a.Manifest.Binary.SHA256, BinaryAt: a.BinaryPath}) if verifyFails >= maxVerifyFails { - s.logger.Printf("app=%s: verify-fail cap reached (%d) — SUSPENDED; not respawning until daemon restart or re-install", a.Manifest.ID, maxVerifyFails) + s.logger.Warnf("app=%s: verify-fail cap reached (%d) — SUSPENDED; not respawning until daemon restart or re-install", a.Manifest.ID, maxVerifyFails) s.writeAuditLine(a, auditEvent{Event: "suspend", Reason: fmt.Sprintf(">=%d consecutive verify failures", maxVerifyFails)}) markerPath := filepath.Join(a.Dir, suspendedMarkerName) if err := os.WriteFile(markerPath, nil, 0o600); err != nil { - s.logger.Printf("app=%s: write suspended marker: %v", a.Manifest.ID, err) + s.logger.Warnf("app=%s: write suspended marker: %v", a.Manifest.ID, err) } s.markSuspended(a.Manifest.ID) return @@ -1019,7 +1045,7 @@ func (s *supervisor) superviseOne(ctx context.Context, a *installedApp) { return } if suspended := s.recordCrash(a.Manifest.ID); suspended { - s.logger.Printf("app=%s exited (code=%d) — SUSPENDED (>%d crashes in %s); not respawning until daemon restart", + s.logger.Warnf("app=%s exited (code=%d) — SUSPENDED (>%d crashes in %s); not respawning until daemon restart", a.Manifest.ID, exitCode, maxCrashesInWindow, crashLoopWindow) s.writeAuditLine(a, auditEvent{Event: "suspend", Reason: fmt.Sprintf(">%d crashes in %s", maxCrashesInWindow, crashLoopWindow)}) // Drop a sentinel file so `pilotctl appstore list` (which @@ -1029,11 +1055,11 @@ func (s *supervisor) superviseOne(ctx context.Context, a *installedApp) { // log still records the event canonically. markerPath := filepath.Join(a.Dir, suspendedMarkerName) if err := os.WriteFile(markerPath, nil, 0o600); err != nil { - s.logger.Printf("app=%s: write suspended marker: %v", a.Manifest.ID, err) + s.logger.Warnf("app=%s: write suspended marker: %v", a.Manifest.ID, err) } return } - s.logger.Printf("app=%s exited (code=%d) — restart in %s", a.Manifest.ID, exitCode, backoff) + s.logger.Warnf("app=%s exited (code=%d) — restart in %s", a.Manifest.ID, exitCode, backoff) select { case <-ctx.Done(): return @@ -1096,7 +1122,7 @@ func (s *supervisor) spawn(ctx context.Context, a *installedApp) int { // verified at the top of its cycle, but a swap could land in the // window between that check and this exec — refuse to launch if so. if err := s.verifyAtSpawn(a); err != nil { - s.logger.Printf("app=%s: spawn-time verify failed: %v — refusing to exec", a.Manifest.ID, err) + s.logger.Warnf("app=%s: spawn-time verify failed: %v — refusing to exec", a.Manifest.ID, err) s.writeAuditLine(a, auditEvent{Event: "verify-fail", Reason: "spawn-time: " + err.Error(), SHA256: a.Manifest.Binary.SHA256, BinaryAt: a.BinaryPath}) return -1 } @@ -1154,7 +1180,7 @@ func (s *supervisor) spawn(ctx context.Context, a *installedApp) int { defer runtime.UnlockOSThread() } if err := cmd.Start(); err != nil { - s.logger.Printf("app=%s start: %v", a.Manifest.ID, err) + s.logger.Warnf("app=%s start: %v", a.Manifest.ID, err) s.writeAuditLine(a, auditEvent{Event: "spawn-fail", Reason: err.Error(), BinaryAt: a.BinaryPath}) return -1 } @@ -1205,7 +1231,7 @@ func (s *supervisor) waitReady(ctx context.Context, a *installedApp, timeout tim } time.Sleep(25 * time.Millisecond) } - s.logger.Printf("app=%s socket did not appear within %s", a.Manifest.ID, timeout) + s.logger.Warnf("app=%s socket did not appear within %s", a.Manifest.ID, timeout) } func (s *supervisor) markReady(appID string) { @@ -1401,7 +1427,7 @@ func (s *supervisor) emitUsage(callerID, appID, method string, ok bool, durMs in } defer func() { if r := recover(); r != nil { - s.logger.Printf("telemetry emitter panicked: %v", r) + s.logger.Warnf("telemetry emitter panicked: %v", r) } }() t.Emit(TelemetryEvent{ diff --git a/plugin/appstore/zz2_supervisor_lifecycle_test.go b/plugin/appstore/zz2_supervisor_lifecycle_test.go index 9163d46..ac2f67b 100644 --- a/plugin/appstore/zz2_supervisor_lifecycle_test.go +++ b/plugin/appstore/zz2_supervisor_lifecycle_test.go @@ -578,7 +578,7 @@ func TestApplyChildResourceLimits_Smoke(t *testing.T) { t.Parallel() // Pass an invalid PID; the function is best-effort and must not panic. logger := newQuietLogger(t) - applyChildResourceLimits(0, defaultChildAddressSpaceLimit, logger) + applyChildResourceLimits(0, defaultChildAddressSpaceLimit, newAppLogger(logger, nil)) } // TestService_AppsBeforeStart returns nil per the docstring. diff --git a/plugin/appstore/zz9_quiet_skips_test.go b/plugin/appstore/zz9_quiet_skips_test.go new file mode 100644 index 0000000..13afb2e --- /dev/null +++ b/plugin/appstore/zz9_quiet_skips_test.go @@ -0,0 +1,113 @@ +package appstore + +import ( + "bytes" + "log" + "log/slog" + "os" + "path/filepath" + "strings" + "testing" +) + +// A dir in the install root with no manifest.json is not an install: an app +// run outside the daemon can keep its state there (the wallet binary keeps +// identity-evm.json in ~/.pilot/apps/io.pilot.wallet). The rescan runs every +// 2 s, and it logged the dir on every tick: 1,574 times in under an hour on +// one Mac. It is logged once, and left alone. +func TestScanInstalled_DirWithoutManifestIsLoggedOnce(t *testing.T) { + t.Parallel() + root := t.TempDir() + state := filepath.Join(root, "io.pilot.wallet", "identity-evm.json") + if err := os.MkdirAll(filepath.Dir(state), 0o700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(state, []byte(`{"key":"kept"}`), 0o600); err != nil { + t.Fatal(err) + } + var logs bytes.Buffer + sup := newSupervisor(Config{InstallRoot: root, CataloguePublisher: testCatPub}, Deps{}, log.New(&logs, "", 0)) + for i := 0; i < 5; i++ { + apps, err := sup.scanInstalled() + if err != nil || len(apps) != 0 { + t.Fatalf("scan %d: %d apps, %v; want none", i, len(apps), err) + } + } + if n := strings.Count(logs.String(), "skip io.pilot.wallet: no manifest.json"); n != 1 { + t.Fatalf("logged %d times over 5 scans, want once:\n%s", n, logs.String()) + } + if b, err := os.ReadFile(state); err != nil || string(b) != `{"key":"kept"}` { + t.Fatalf("the app's state file was touched: %q, %v", b, err) + } +} + +// Every skip reason is logged once per dir, and again only when the reason +// changes (here: a manifest that stops parsing differently). +func TestScanInstalled_SkipIsLoggedAgainOnlyWhenItsReasonChanges(t *testing.T) { + t.Parallel() + root := t.TempDir() + mf := filepath.Join(root, "io.test.broken", "manifest.json") + if err := os.MkdirAll(filepath.Dir(mf), 0o700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(mf, []byte("{not json"), 0o600); err != nil { + t.Fatal(err) + } + var logs bytes.Buffer + sup := newSupervisor(Config{InstallRoot: root, CataloguePublisher: testCatPub}, Deps{}, log.New(&logs, "", 0)) + scan := func() { + t.Helper() + if _, err := sup.scanInstalled(); err != nil { + t.Fatal(err) + } + } + scan() + scan() + scan() + if n := strings.Count(logs.String(), "skip io.test.broken:"); n != 1 { + t.Fatalf("logged %d times over 3 scans, want once:\n%s", n, logs.String()) + } + if err := os.WriteFile(mf, []byte(`{"id": 7}`), 0o600); err != nil { + t.Fatal(err) + } + scan() + scan() + if n := strings.Count(logs.String(), "skip io.test.broken:"); n != 2 { + t.Fatalf("logged %d times after the reason changed, want 2:\n%s", n, logs.String()) + } +} + +// With Config.Slog set the messages carry a level: routine ones INFO, +// problems WARN, so a reader of the daemon's log (the Mac app counts the +// level-less lines as warnings) tells them apart. +func TestSlogCarriesTheLevel(t *testing.T) { + t.Parallel() + root := t.TempDir() + if err := os.MkdirAll(filepath.Join(root, "io.pilot.wallet"), 0o700); err != nil { + t.Fatal(err) + } + mf := filepath.Join(root, "io.test.broken", "manifest.json") + if err := os.MkdirAll(filepath.Dir(mf), 0o700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(mf, []byte("{not json"), 0o600); err != nil { + t.Fatal(err) + } + var out bytes.Buffer + sl := slog.New(slog.NewTextHandler(&out, nil)) + var std bytes.Buffer + sup := newSupervisor(Config{InstallRoot: root, CataloguePublisher: testCatPub, Slog: sl}, Deps{}, log.New(&std, "", 0)) + if _, err := sup.scanInstalled(); err != nil { + t.Fatal(err) + } + got := out.String() + if !strings.Contains(got, `level=INFO msg="appstore: skip io.pilot.wallet: no manifest.json`) { + t.Errorf("no-manifest skip not logged at INFO through slog:\n%s", got) + } + if !strings.Contains(got, `level=WARN msg="appstore: skip io.test.broken: parse:`) { + t.Errorf("unparseable manifest not logged at WARN through slog:\n%s", got) + } + if std.Len() != 0 { + t.Errorf("with Slog set, the log.Logger still got:\n%s", std.String()) + } +} From d7a079f2eaff5e8c1230768eb33290014b489adc Mon Sep 17 00:00:00 2001 From: Teo Calin Date: Thu, 8 Oct 2026 14:49:29 +0300 Subject: [PATCH 2/2] appstore: no per-tick or routine warnings left Review of the leveled logs found warnings that would still repeat or that routine operations raise, now that the daemon will show WARN: - A refused downgrade stays on disk and was logged and audited on every rescan (about 1,800 times an hour). A rescan error and a resume marker that cannot be removed repeated the same way. These are logged once per condition (warnOnce), and again if it changes or comes back. - Uninstall deletes the app's dir, and the supervise goroutine's last audit lines then failed with "audit open: no such file" as warnings. An audit write into a removed dir is now silent. - pilotctl's install swaps a new dir in under the running app, taking its socket path with it: watchSocket warned "socket vanished", killed the app and the exit counted as a crash. When the install dir itself was replaced, it is now logged as a reinstall (INFO), the exit is not a crash, and the loop waits one rescan so an upgrade's own restart wins over re-verifying the new binary against the old pin. - A manifest.json that is a dangling symlink is a read-manifest warning, not "not an installed app". Co-Authored-By: Claude Opus 5.5 --- plugin/appstore/logging.go | 48 +++++++++++ plugin/appstore/reap.go | 14 +++- plugin/appstore/supervisor.go | 65 +++++++++++---- plugin/appstore/zz9_quiet_skips_test.go | 102 ++++++++++++++++++++++++ 4 files changed, 210 insertions(+), 19 deletions(-) diff --git a/plugin/appstore/logging.go b/plugin/appstore/logging.go index 15093b6..e9e28bd 100644 --- a/plugin/appstore/logging.go +++ b/plugin/appstore/logging.go @@ -7,6 +7,7 @@ import ( "fmt" "log" "log/slog" + "time" ) // appLogger carries the app store's messages with a level: Printf for @@ -40,3 +41,50 @@ func (l *appLogger) logf(level slog.Level, format string, args ...any) { } l.std.Printf(format, args...) } + +// warnOnce logs msg as a warning unless the last warning logged for key was +// the same message, and reports whether it logged. For a condition the +// rescan finds again on every tick: logged when it starts or changes, not +// every few seconds. clearWarned forgets key once the condition is over, so +// it is logged again if it comes back. +func (s *supervisor) warnOnce(key, msg string) bool { + s.sigMu.Lock() + same := s.warned[key] == msg + s.warned[key] = msg + s.sigMu.Unlock() + if same { + return false + } + s.logger.Warnf("%s", msg) + return true +} + +func (s *supervisor) clearWarned(key string) { + s.sigMu.Lock() + delete(s.warned, key) + s.sigMu.Unlock() +} + +// markReinstalled and takeReinstalled carry watchSocket's "the install was +// replaced" to the supervise loop, so that exit is not counted as a crash. +func (s *supervisor) markReinstalled(id string) { + s.mu.Lock() + s.reinstalled[id] = true + s.mu.Unlock() +} + +func (s *supervisor) takeReinstalled(id string) bool { + s.mu.Lock() + defer s.mu.Unlock() + r := s.reinstalled[id] + delete(s.reinstalled, id) + return r +} + +// rescanInterval is how often run() rescans the install root. +func (s *supervisor) rescanInterval() time.Duration { + if s.cfg.RescanInterval > 0 { + return s.cfg.RescanInterval + } + return defaultRescanInterval +} diff --git a/plugin/appstore/reap.go b/plugin/appstore/reap.go index c35d469..6622b48 100644 --- a/plugin/appstore/reap.go +++ b/plugin/appstore/reap.go @@ -177,6 +177,10 @@ func (s *supervisor) watchSocket(ctx context.Context, a *installedApp, pid int, t := time.NewTicker(interval) defer t.Stop() seen := false + // The install dir as it was when this process started. pilotctl's + // install swaps in a new dir under the same path, which takes the + // socket path with it: that is a reinstall, not a lost socket. + origDir, _ := os.Stat(a.Dir) for { select { case <-ctx.Done(): @@ -193,8 +197,14 @@ func (s *supervisor) watchSocket(ctx context.Context, a *installedApp, pid int, case err == nil: seen = true case seen && os.IsNotExist(err): - s.logger.Warnf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid) - s.writeAuditLine(a, auditEvent{Event: "socket-lost", PID: pid}) + if cur, cerr := os.Stat(a.Dir); origDir != nil && cerr == nil && !os.SameFile(origDir, cur) { + s.logger.Printf("app=%s: reinstalled while running (pid=%d) — restarting it into the new install", a.Manifest.ID, pid) + s.writeAuditLine(a, auditEvent{Event: "reinstalled", PID: pid}) + s.markReinstalled(a.Manifest.ID) + } else { + s.logger.Warnf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid) + s.writeAuditLine(a, auditEvent{Event: "socket-lost", PID: pid}) + } if syscall.Kill(-pid, syscall.SIGTERM) != nil { _ = syscall.Kill(pid, syscall.SIGTERM) } diff --git a/plugin/appstore/supervisor.go b/plugin/appstore/supervisor.go index 8bb67c8..1c53fce 100644 --- a/plugin/appstore/supervisor.go +++ b/plugin/appstore/supervisor.go @@ -87,6 +87,9 @@ func (s *supervisor) writeAuditLine(a *installedApp, ev auditEvent) { path := filepath.Join(a.Dir, supervisorLogName) s.rotateAuditIfLarge(a.Dir) f, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) + if errors.Is(err, fs.ErrNotExist) { + return // the app's dir is gone: it was uninstalled + } if err != nil { s.logger.Warnf("audit open %s: %v", path, err) return @@ -172,12 +175,18 @@ type supervisor struct { crashes map[string]*crashRecord // app_id → sliding-window crash counter appCancel map[string]context.CancelFunc // app_id → cancel its per-app context (used to stop a supervise goroutine on detected uninstall) - // sigMu guards sigFails and misnamed. Kept separate from mu because + // sigMu guards sigFails, skipLogged and warned. Kept separate from mu because // this bookkeeping happens inside scanInstalled, which must not hold // the main lock while walking the filesystem. sigMu sync.Mutex sigFails map[string]*sigFailRecord // install-dir name → manifest-signature failure state skipLogged map[string]string // install-dir name → the skip line last logged for it (noteSkipped) + warned map[string]string // condition key → the warning last logged for it (warnOnce) + + // reinstalled marks an app whose running process watchSocket stopped + // because its install dir was replaced (pilotctl reinstalled it): its + // exit is not a crash. Guarded by mu. + reinstalled map[string]bool } func newSupervisor(cfg Config, deps Deps, logger *log.Logger) *supervisor { @@ -186,15 +195,17 @@ func newSupervisor(cfg Config, deps Deps, logger *log.Logger) *supervisor { deps.Telemetry = noopEmitter{} } return &supervisor{ - cfg: cfg, - deps: deps, - logger: newAppLogger(logger, cfg.Slog), - installed: map[string]*installedApp{}, - ready: map[string]bool{}, - crashes: map[string]*crashRecord{}, - appCancel: map[string]context.CancelFunc{}, - sigFails: map[string]*sigFailRecord{}, - skipLogged: map[string]string{}, + cfg: cfg, + deps: deps, + logger: newAppLogger(logger, cfg.Slog), + installed: map[string]*installedApp{}, + ready: map[string]bool{}, + crashes: map[string]*crashRecord{}, + appCancel: map[string]context.CancelFunc{}, + sigFails: map[string]*sigFailRecord{}, + skipLogged: map[string]string{}, + warned: map[string]string{}, + reinstalled: map[string]bool{}, } } @@ -476,7 +487,7 @@ func (s *supervisor) scanInstalled() ([]*installedApp, error) { dir := filepath.Join(s.cfg.InstallRoot, e.Name()) mfPath := filepath.Join(dir, "manifest.json") data, err := os.ReadFile(mfPath) - if errors.Is(err, fs.ErrNotExist) { + if _, lerr := os.Lstat(mfPath); errors.Is(err, fs.ErrNotExist) && errors.Is(lerr, fs.ErrNotExist) { // Not an install: an app run outside the daemon can keep its // state under its id here (the wallet's identity-evm.json). skipped[e.Name()] = skipNote{msg: fmt.Sprintf("skip %s: no manifest.json — not an installed app; left alone", e.Name())} @@ -703,9 +714,10 @@ func (s *supervisor) run(ctx context.Context, apps []*installedApp) { func (s *supervisor) rescanForNew() []*installedApp { apps, err := s.scanInstalled() if err != nil { - s.logger.Warnf("rescan: %v", err) + s.warnOnce("rescan", fmt.Sprintf("rescan: %v", err)) return nil } + s.clearWarned("rescan") s.mu.Lock() defer s.mu.Unlock() var fresh []*installedApp @@ -742,12 +754,16 @@ func (s *supervisor) rescanForNew() []*installedApp { continue } if compareVersions(a.Manifest.AppVersion, existing.Manifest.AppVersion) < 0 { - s.logger.Warnf("rescan: downgrade refused: app=%s new=%s old=%s — keeping existing version", - a.Manifest.ID, a.Manifest.AppVersion, existing.Manifest.AppVersion) - s.writeAuditLine(a, auditEvent{Event: "downgrade-refused", - Reason: fmt.Sprintf("rescan: refusing %s (existing %s)", a.Manifest.AppVersion, existing.Manifest.AppVersion)}) + // The older install stays on disk, so every rescan finds it + // again: say so once per version and binary on disk. + if s.warnOnce("downgrade/"+a.Manifest.ID, fmt.Sprintf("rescan: downgrade refused: app=%s new=%s (%s) old=%s — keeping existing version", + a.Manifest.ID, a.Manifest.AppVersion, shortSHA(a.Manifest.Binary.SHA256), existing.Manifest.AppVersion)) { + s.writeAuditLine(a, auditEvent{Event: "downgrade-refused", + Reason: fmt.Sprintf("rescan: refusing %s (existing %s)", a.Manifest.AppVersion, existing.Manifest.AppVersion)}) + } continue } + s.clearWarned("downgrade/" + a.Manifest.ID) // Version upgrade detected on disk: cancel the old supervise // goroutine and register the new manifest. The old app // will be torn down by its ctx cancel; the rescan loop @@ -853,9 +869,10 @@ func (s *supervisor) rescanForResume() []*installedApp { } // Consume the marker first so a partial failure doesn't loop. if err := os.Remove(markerPath); err != nil { - s.logger.Warnf("rescan: app id=%s: remove resume marker: %v", id, err) + s.warnOnce("resume/"+id, fmt.Sprintf("rescan: app id=%s: remove resume marker: %v", id, err)) continue } + s.clearWarned("resume/" + id) // Clear the crash record so the new supervise goroutine // starts with a fresh window. Also drop the stale cancel — // the old goroutine has already returned (suspended apps @@ -1044,6 +1061,20 @@ func (s *supervisor) superviseOne(ctx context.Context, a *installedApp) { if ctx.Err() != nil { return } + if s.takeReinstalled(a.Manifest.ID) { + // Stopped by watchSocket because pilotctl replaced the install: + // not a crash. An upgrade's rescan cancels this goroutine and + // starts the new version; give it one rescan to do so, rather + // than verifying the new binary against this manifest's pin. + // A reinstall of the same bundle is restarted here. + select { + case <-ctx.Done(): + return + case <-time.After(s.rescanInterval() + time.Second): + } + backoff = time.Second + continue + } if suspended := s.recordCrash(a.Manifest.ID); suspended { s.logger.Warnf("app=%s exited (code=%d) — SUSPENDED (>%d crashes in %s); not respawning until daemon restart", a.Manifest.ID, exitCode, maxCrashesInWindow, crashLoopWindow) diff --git a/plugin/appstore/zz9_quiet_skips_test.go b/plugin/appstore/zz9_quiet_skips_test.go index 13afb2e..e16d0e9 100644 --- a/plugin/appstore/zz9_quiet_skips_test.go +++ b/plugin/appstore/zz9_quiet_skips_test.go @@ -2,12 +2,15 @@ package appstore import ( "bytes" + "context" + "io" "log" "log/slog" "os" "path/filepath" "strings" "testing" + "time" ) // A dir in the install root with no manifest.json is not an install: an app @@ -111,3 +114,102 @@ func TestSlogCarriesTheLevel(t *testing.T) { t.Errorf("with Slog set, the log.Logger still got:\n%s", std.String()) } } + +// pilotctl's install swaps a new dir in under the same path, which takes the +// running app's socket with it. That is a reinstall, logged as one (INFO) and +// marked so the supervise loop does not count the exit as a crash; a socket +// that vanishes from the same dir is still a warning. +func TestWatchSocketTellsAReinstallFromALostSocket(t *testing.T) { + root := t.TempDir() + dir := filepath.Join(root, "io.test.reap") + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + a := fakeApp(dir, "/opt/pilot/apps/io.test.reap/bin/reap-app", "") + cmd := startFakeApp(t, a.BinaryPath, "--socket", a.SocketPath) + if err := os.WriteFile(a.SocketPath, nil, 0o600); err != nil { + t.Fatal(err) + } + var logs bytes.Buffer + s := newSupervisor(Config{}, Deps{}, log.New(&logs, "", 0)) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + watched := make(chan struct{}) + go func() { s.watchSocket(ctx, a, cmd.Process.Pid, 20*time.Millisecond); close(watched) }() + time.Sleep(100 * time.Millisecond) // let the watcher see the socket + + // The swap: the live dir moves aside, a fresh one takes its path. + if err := os.Rename(dir, dir+".previous"); err != nil { + t.Fatal(err) + } + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + if !waitExited(cmd, 5*time.Second) { + t.Fatal("app kept running after it was reinstalled") + } + <-watched // its log and mark are written before it returns + if !strings.Contains(logs.String(), "reinstalled while running") || strings.Contains(logs.String(), "vanished") { + t.Fatalf("want the reinstall line, not the lost-socket warning:\n%s", logs.String()) + } + if !s.takeReinstalled("io.test.reap") { + t.Fatal("the reinstall was not marked: its exit would count as a crash") + } +} + +// A refused downgrade stays on disk, so every rescan finds it: it is logged +// (and audited) once, not every tick. +func TestRescanLogsARefusedDowngradeOnce(t *testing.T) { + root := t.TempDir() + const id = "io.test.app" + sha := strings.Repeat("a", 64) + writeAppDirWithVersionSHA(t, root, id, "1.0.0", sha) + var logs bytes.Buffer + sup := newSupervisor(Config{InstallRoot: root, CataloguePublisher: testCatPub, RescanInterval: time.Hour}, Deps{}, log.New(&logs, "", 0)) + newer := &installedApp{Dir: filepath.Join(root, id), Manifest: parseDummyManifest(t, id)} + newer.Manifest.AppVersion = "2.0.0" + sup.mu.Lock() + sup.installed[id] = newer + sup.mu.Unlock() + for i := 0; i < 5; i++ { + sup.rescanForNew() + } + if n := strings.Count(logs.String(), "downgrade refused"); n != 1 { + t.Fatalf("logged %d times over 5 rescans, want once:\n%s", n, logs.String()) + } +} + +// Uninstall deletes the app's dir; the supervise goroutine's last audit +// lines then have nowhere to go. That is the uninstall, not a problem. +func TestAuditLineForAnUninstalledAppIsSilent(t *testing.T) { + t.Parallel() + var logs bytes.Buffer + sup := newSupervisor(Config{}, Deps{}, log.New(&logs, "", 0)) + a := fakeApp(filepath.Join(t.TempDir(), "gone"), "/bin/true", "") + sup.writeAuditLine(a, auditEvent{Event: "exit"}) + if logs.Len() != 0 { + t.Fatalf("audit write into a removed dir logged:\n%s", logs.String()) + } +} + +// A manifest.json that is a dangling symlink is not "no manifest": it is a +// broken install, a warning. +func TestScanInstalled_DanglingManifestSymlinkIsAWarning(t *testing.T) { + t.Parallel() + root := t.TempDir() + dir := filepath.Join(root, "io.test.link") + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + if err := os.Symlink(filepath.Join(root, "nowhere.json"), filepath.Join(dir, "manifest.json")); err != nil { + t.Fatal(err) + } + var out bytes.Buffer + sup := newSupervisor(Config{InstallRoot: root, CataloguePublisher: testCatPub, Slog: slog.New(slog.NewTextHandler(&out, nil))}, Deps{}, log.New(io.Discard, "", 0)) + if _, err := sup.scanInstalled(); err != nil { + t.Fatal(err) + } + if !strings.Contains(out.String(), `level=WARN msg="appstore: skip io.test.link: read manifest:`) { + t.Fatalf("dangling manifest symlink not a read-manifest warning:\n%s", out.String()) + } +}