diff --git a/CHANGELOG.md b/CHANGELOG.md index e4e96ba3..54ef9223 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,47 @@ Detailed per-release notes are on the ## [Unreleased] ### Added +- **The daemon caps its own log file.** launchd never rotates the daemon's + `StandardOutPath`/`StandardErrorPath` (`~/.pilot/daemon.log`), which grew + without bound — 22 MB on one laptop. When stderr is a regular file the + daemon now checks it every minute and, past `-log-max-size` MB (default 50; + `0` disables), copy-truncates it into gzipped generations + `daemon.log.pilot.1.gz` … `daemon.log.pilot.N.gz` (`-log-max-backups`, + default 3). Truncation is safe for every writer — the file is opened + append-only and shared by child processes. Both flags can also be set in + `~/.pilot/config.json` (`log_max_size`, `log_max_backups`). No-op when the + output goes to journald, a pipe or a terminal. + - By default only a log Pilot set up is rotated: one inside `~/.pilot`, + where install.sh's launchd job and `pilotctl daemon start` put it (also + `$PILOT_HOME/.pilot`), and the Homebrew service's + `$(brew --prefix)/var/log/pilot-daemon.log` when the daemon is the one + `brew install pilotprotocol` installed (`brew services`, launchd or + systemd). If you send the daemon's output somewhere else, rotation stays + off unless you set `-log-max-size` explicitly, on the command line or in + `config.json`, so your own rotation (logrotate, newsyslog) keeps working + as before. + - A rotation interrupted by a crash or kill is finished by the next + rotation of that log. In `~/.pilot` this includes a rotation left under + the `pilot-.log` name of a daemon that `pilotctl daemon start` + launched earlier. Only those names are finished this way, so another + program's `.pilot.1` is never taken for one. A rotation holds its + uncompressed copy (`.pilot.1`) locked with `flock` until it is + compressed, so a copy that another running daemon is still working on + is left alone. + - If the log cannot be truncated (an append-only file, or a filesystem + that refuses it), no backup is lost. The round's copy is removed, the + generations are put back, and the next attempt waits twice as long as + the last, up to about an hour. + - It never touches files it did not create. The `.pilot` infix keeps its + backups apart from logrotate's and newsyslog's names (`daemon.log.1`, + `daemon.log.2.gz`, …). It skips a symlink or another user's file at one + of its own names, and creates its files with `O_EXCL|O_NOFOLLOW`. If + other users can create files in the log's directory, it only truncates + and keeps no backups. That is the case when the directory is writable + by others, is owned by another user, or is writable by a group other + than the user's own private group. A `~/.pilot` that is group-writable + only because of the umask 002 on Ubuntu, Debian or Fedora (the group + is the user's own, with no other members) keeps its backups. - **Opt out of automatic app-store updates with `PILOT_APP_UPDATE_OPT_OUT`.** The `pilot-updater` keeps installed apps current by periodically running `pilotctl appstore upgrade --all`. Set `PILOT_APP_UPDATE_OPT_OUT=true` in the @@ -20,6 +61,17 @@ Detailed per-release notes are on the `PILOT_UPDATER_NO_APP_UPGRADE` as a back-compat alias. ### Fixed +- **Watchdog restarts no longer orphan app-store apps.** When the inbound-path + watchdog gave up on a wedged transport it called `os.Exit(86)` directly, + skipping the graceful shutdown that stops plugins — so every installed app + (each in its own process group) was left running on every respawn. One + laptop accumulated 94 copies of each of 12 apps (~2.8 GB RSS) in a week. + The watchdog now asks the daemon's shutdown loop to stop the daemon and its + plugins, then exits with code 86 as before so launchd/systemd still respawn + it; a 15 s hard deadline forces the exit if the teardown hangs. Startup + failures after plugins have started now stop them before exiting, too. + (Complements the app-store's orphan reaping at spawn, + pilot-protocol/app-store#38.) - **The `pilotctl skills disable` opt-out now survives updates and explicit reconciles.** A forced reconcile — `pilotctl skills check`, `pilotctl update`, or an installer re-run — bypassed the disabled flag and re-injected skills a diff --git a/cmd/daemon/logrotation.go b/cmd/daemon/logrotation.go new file mode 100644 index 00000000..177e5542 --- /dev/null +++ b/cmd/daemon/logrotation.go @@ -0,0 +1,97 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "flag" + "os" + "path/filepath" + "strings" +) + +// pilotDirs returns the directories the daemon's log is in when Pilot +// itself set it up, which is where -log-max-size applies by default: +// launchd's StandardErrorPath (~/.pilot/daemon.log, from install.sh) and +// `pilotctl daemon start` (~/.pilot/pilot-.log, under $PILOT_HOME +// when that is set). pilotLogFiles adds the Homebrew service's log. A log +// an operator redirected anywhere else may already be rotated by other +// means, so it is left alone unless -log-max-size is set explicitly +// (flagExplicit). +func pilotDirs() []string { + var dirs []string + if home, err := os.UserHomeDir(); err == nil { + dirs = append(dirs, filepath.Join(home, ".pilot")) + } + if h := os.Getenv("PILOT_HOME"); h != "" { + dirs = append(dirs, filepath.Join(h, ".pilot")) + } + return dirs +} + +// pilotLogFiles returns the logs outside pilotDirs that Pilot itself set +// up, where -log-max-size also applies by default: the `brew services` +// log when this daemon is the one Pilot's Homebrew formula installed. +func pilotLogFiles() []string { + exe, err := os.Executable() + if err != nil { + return nil + } + if log, ok := homebrewServiceLog(exe); ok { + return []string{log} + } + return nil +} + +// homebrewServiceLog returns the file `brew services` sends the daemon's +// stdout and stderr to when exe is the pilot-daemon of Pilot's Homebrew +// formula (TeoSlayer/homebrew-pilot, Formula/pilotprotocol.rb): +// /Cellar/pilotprotocol//bin/pilot-daemon, which the +// service runs through the /opt/pilotprotocol link. The formula's +// service block sets log_path and error_log_path to +// var/"log/pilot-daemon.log", which launchd (StandardOutPath, +// StandardErrorPath) or systemd (StandardOutput=append:) opens and +// nothing rotates. Only that one file is in scope, not the rest of +// /var/log, which belongs to other formulae. Keep the names here +// in step with the formula. +func homebrewServiceLog(exe string) (string, bool) { + resolved, err := filepath.EvalSymlinks(exe) + if err != nil { + return "", false + } + bin := filepath.Dir(resolved) + formula := filepath.Dir(filepath.Dir(bin)) + cellar := filepath.Dir(formula) + if filepath.Base(resolved) != "pilot-daemon" || + filepath.Base(bin) != "bin" || + filepath.Base(formula) != "pilotprotocol" || + filepath.Base(cellar) != "Cellar" { + return "", false + } + return filepath.Join(filepath.Dir(cellar), "var", "log", "pilot-daemon.log"), true +} + +// flagExplicit reports whether flag name was set on the command line or +// in the config file. config.ApplyToFlags sets config values without +// marking the flag as set, so the config map is checked directly, the +// way ApplyToFlags reads it: the hyphenated key, else the underscored +// one, and only the value types it applies. +func flagExplicit(name string, fileConfig map[string]interface{}) bool { + explicit := false + flag.Visit(func(f *flag.Flag) { + if f.Name == name { + explicit = true + } + }) + if explicit { + return true + } + val, ok := fileConfig[name] + if !ok { + val = fileConfig[strings.ReplaceAll(name, "-", "_")] + } + switch val.(type) { + case string, float64, bool: + return true + } + return false +} diff --git a/cmd/daemon/logrotation_test.go b/cmd/daemon/logrotation_test.go new file mode 100644 index 00000000..f3b83f33 --- /dev/null +++ b/cmd/daemon/logrotation_test.go @@ -0,0 +1,132 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "flag" + "os" + "path/filepath" + "reflect" + "testing" +) + +// TestFlagExplicit: -log-max-size counts as explicit — rotating a log +// outside ~/.pilot — when given on the command line or in the config +// file, under either key spelling and only with a value ApplyToFlags +// would apply; the flag's default alone does not. +func TestFlagExplicit(t *testing.T) { + saved := flag.CommandLine + t.Cleanup(func() { flag.CommandLine = saved }) + parse := func(args ...string) { + t.Helper() + flag.CommandLine = flag.NewFlagSet("pilot-daemon", flag.ContinueOnError) + flag.Int("log-max-size", 50, "") + flag.Int("log-max-backups", 3, "") + if err := flag.CommandLine.Parse(args); err != nil { + t.Fatal(err) + } + } + + for _, tc := range []struct { + name string + args []string + cfg map[string]interface{} + want bool + }{ + {"default", nil, nil, false}, + {"other flag set", []string{"-log-max-backups", "5"}, map[string]interface{}{"log_max_backups": float64(5)}, false}, + {"command line", []string{"-log-max-size", "50"}, nil, true}, + {"command line 0", []string{"-log-max-size=0"}, nil, true}, + {"config underscore", nil, map[string]interface{}{"log_max_size": float64(20)}, true}, + {"config hyphen", nil, map[string]interface{}{"log-max-size": "20"}, true}, + {"config null", nil, map[string]interface{}{"log_max_size": nil}, false}, + {"config object", nil, map[string]interface{}{"log_max_size": map[string]interface{}{}}, false}, + // ApplyToFlags reads the hyphenated key when present, even when + // its value is one it ignores. + {"config hyphen null shadows underscore", nil, map[string]interface{}{"log-max-size": nil, "log_max_size": float64(20)}, false}, + } { + parse(tc.args...) + if got := flagExplicit("log-max-size", tc.cfg); got != tc.want { + t.Errorf("%s: flagExplicit = %v, want %v", tc.name, got, tc.want) + } + } +} + +// TestPilotDirs: the default rotation scope is ~/.pilot, plus +// $PILOT_HOME/.pilot where `pilotctl daemon start` keeps its logs when +// PILOT_HOME is set. +func TestPilotDirs(t *testing.T) { + home := t.TempDir() + t.Setenv("HOME", home) + t.Setenv("PILOT_HOME", "") + if got, want := pilotDirs(), []string{filepath.Join(home, ".pilot")}; !reflect.DeepEqual(got, want) { + t.Fatalf("pilotDirs = %v, want %v", got, want) + } + + alt := t.TempDir() + t.Setenv("PILOT_HOME", alt) + want := []string{filepath.Join(home, ".pilot"), filepath.Join(alt, ".pilot")} + if got := pilotDirs(); !reflect.DeepEqual(got, want) { + t.Fatalf("pilotDirs = %v, want %v", got, want) + } +} + +// TestHomebrewServiceLog: the pilot-daemon Pilot's Homebrew formula +// installed maps to the log its `brew services` block sets, +// /var/log/pilot-daemon.log — however it was started: through +// /opt/pilotprotocol (the service's run path), the linked +// /bin, or the Cellar itself. Any other binary maps to nothing. +func TestHomebrewServiceLog(t *testing.T) { + prefix := t.TempDir() + // macOS's temp dir is under the /var -> /private/var link; the + // result is built from the resolved executable path. + realPrefix, err := filepath.EvalSymlinks(prefix) + if err != nil { + t.Fatal(err) + } + file := func(rel string) string { + t.Helper() + p := filepath.Join(prefix, rel) + if err := os.MkdirAll(filepath.Dir(p), 0o755); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(p, nil, 0o755); err != nil { + t.Fatal(err) + } + return p + } + link := func(target, rel string) string { + t.Helper() + p := filepath.Join(prefix, rel) + if err := os.MkdirAll(filepath.Dir(p), 0o755); err != nil { + t.Fatal(err) + } + if err := os.Symlink(target, p); err != nil { + t.Fatal(err) + } + return p + } + + cellar := file("Cellar/pilotprotocol/1.13.9/bin/pilot-daemon") + opt := filepath.Join(link("../Cellar/pilotprotocol/1.13.9", "opt/pilotprotocol"), "bin", "pilot-daemon") + linked := link("../Cellar/pilotprotocol/1.13.9/bin/pilot-daemon", "bin/pilot-daemon") + want := filepath.Join(realPrefix, "var", "log", "pilot-daemon.log") + for _, exe := range []string{cellar, opt, linked} { + if got, ok := homebrewServiceLog(exe); !ok || got != want { + t.Errorf("homebrewServiceLog(%s) = (%q, %v), want (%q, true)", exe, got, ok, want) + } + } + + for _, exe := range []string{ + file(".pilot/bin/pilot-daemon"), // install.sh + file("usr/local/bin/pilot-daemon"), // a manual install + file("Cellar/otherformula/1.0/bin/pilot-daemon"), // another formula + file("Cellar/pilotprotocol/1.13.9/bin/pilotctl"), // another binary + file("Cellar/pilotprotocol/1.13.9/libexec/pilot-daemon"), // not the formula's bin + filepath.Join(prefix, "Cellar/pilotprotocol/9.9.9/bin/pilot-daemon"), // missing + } { + if got, ok := homebrewServiceLog(exe); ok { + t.Errorf("homebrewServiceLog(%s) = %q, want no Homebrew service log", exe, got) + } + } +} diff --git a/cmd/daemon/main.go b/cmd/daemon/main.go index efff87a9..8f563556 100644 --- a/cmd/daemon/main.go +++ b/cmd/daemon/main.go @@ -23,6 +23,7 @@ import ( "github.com/pilot-protocol/common/driver" "github.com/pilot-protocol/common/logging" "github.com/pilot-protocol/pilotprotocol/internal/enterprisecontrol" + "github.com/pilot-protocol/pilotprotocol/internal/logcap" "github.com/pilot-protocol/pilotprotocol/internal/managedsdk/authority" "github.com/pilot-protocol/pilotprotocol/internal/motd" "github.com/pilot-protocol/pilotprotocol/pkg/daemon" @@ -114,6 +115,8 @@ func main() { showVersion := flag.Bool("version", false, "print version and exit") logLevel := flag.String("log-level", "info", "log level (debug, info, warn, error)") logFormat := flag.String("log-format", "text", "log format (text, json)") + logMaxSize := flag.Int("log-max-size", 50, "rotate the daemon log once it exceeds this many MB (copy-truncate into gzipped .pilot.N.gz backups). By default only a log Pilot set up is rotated: one inside ~/.pilot (install.sh's launchd daemon.log, pilotctl's pilot-.log) or the Homebrew service's /var/log/pilot-daemon.log; a log elsewhere only when this is set explicitly, here or in config.json. 0 disables") + logMaxBackups := flag.Int("log-max-backups", 3, "gzipped generations kept by -log-max-size rotation (.pilot.1.gz ... .pilot.N.gz); 0 keeps none") sandbox := flag.Bool("sandbox", false, "restrict all file I/O to the sandbox directory (see -sandbox-dir)") sandboxDir := flag.String("sandbox-dir", "", "confinement root when -sandbox is set (default: ~/.pilot)") motdFeedURL := flag.String("motd-feed-url", motd.DefaultFeedURL, "message-of-the-day feed URL (empty to disable); overridden by $PILOT_MOTD_URL") @@ -156,12 +159,14 @@ func main() { } } } + var fileConfig map[string]interface{} if *configPath != "" { cfg, err := config.Load(*configPath) if err != nil { log.Fatalf("load config: %v", err) } config.ApplyToFlags(cfg) + fileConfig = cfg } if *enterpriseControlPath == "" { if discovered, ok := discoverManagedEnterpriseControl(); ok { @@ -220,6 +225,19 @@ func main() { *motdFeedURL = profileOptions.MOTDFeedURL logging.Setup(*logLevel, *logFormat) + // launchd never rotates StandardOutPath/StandardErrorPath (daemon.log + // reached 22 MB on one laptop), so cap it from the inside. No-op when + // stderr isn't a regular file (journald, a terminal, a pipe), and by + // default for a log Pilot did not set up (outside ~/.pilot, and not + // the Homebrew service's), which an operator may rotate by other + // means. Lives for the daemon's lifetime; process exit stops it. + logcap.Watch(context.Background(), os.Stderr, logcap.Options{ + MaxBytes: int64(*logMaxSize) << 20, + MaxBackups: *logMaxBackups, + Anywhere: flagExplicit("log-max-size", fileConfig), + Within: pilotDirs(), + Files: pilotLogFiles(), + }, time.Minute) // Sandbox: validate all configured file paths are under the confinement // root before the daemon touches the filesystem. Network paths are unaffected. @@ -501,7 +519,8 @@ func main() { // Plugin Start methods don't depend on d.Start having run; ports // and tunnels are constructed in daemon.New. if err := rt.StartPlugins(context.Background()); err != nil { - log.Fatalf("plugin startup: %v", err) + // StartAll leaves the plugins it already started running. + fatalAfterPluginStart(rt.StopPlugins, "plugin startup: %v", err) } // PILOT-343/344/345: apply rate-limit whitelists BEFORE Start so the @@ -512,8 +531,13 @@ func main() { applyNodeIDWhitelist("reply", *replyWhitelist, "PILOT_REPLY_WHITELIST", d.SetReplyWhitelist, d.SetReplyWhitelistMatchAll) applyNodeIDWhitelist("rekey", *rekeyWhitelist, "PILOT_REKEY_WHITELIST", d.SetRekeyWhitelist, d.SetRekeyWhitelistMatchAll) + // Route the daemon's supervisor-respawn exits (rx watchdog) through + // the shutdown loop below instead of an immediate os.Exit, so they + // stop the plugins — and the app-store's child apps — first. + daemon.SetExitHandler(forwardExitRequest) + if err := d.Start(); err != nil { - log.Fatalf("daemon start: %v", err) + fatalAfterPluginStart(rt.StopPlugins, "daemon start: %v", err) } rolloutRefreshCtx, rolloutRefreshCancel := context.WithCancel(context.Background()) @@ -612,47 +636,25 @@ func main() { // deliberate restart-time administrative change. sig := make(chan os.Signal, 1) signal.Notify(sig, syscall.SIGINT, syscall.SIGTERM, syscall.SIGHUP) - restartRequested := false -shutdownLoop: - for { - select { - case received := <-sig: - if received == syscall.SIGHUP { - if enterpriseControls == nil { - slog.Warn("enterprise control reload ignored: no attachment is configured") - } else if err := enterpriseControls.Reload(); err != nil { - slog.Error("enterprise control reload rejected; keeping current signed state", "err", err) - } else { - slog.Info("enterprise control reloaded") - } - continue - } - break shutdownLoop - case lifecycle := <-remoteLifecycleRequests: - restartRequested = lifecycle == "restart" - break shutdownLoop + cause := awaitShutdown(sig, remoteLifecycleRequests, supervisorExitRequests, func() { + if enterpriseControls == nil { + slog.Warn("enterprise control reload ignored: no attachment is configured") + } else if err := enterpriseControls.Reload(); err != nil { + slog.Error("enterprise control reload rejected; keeping current signed state", "err", err) + } else { + slog.Info("enterprise control reloaded") } - } + }) signal.Stop(sig) rolloutRefreshCancel() receiptExportCancel() fleetControlCancel() - // Order matters: Daemon.Stop publishes daemon.shutting_down to the - // bus before tearing down ports/IPC/tunnels. Plugins (notably - // webhook) are still subscribed at that point, so the event flows - // through. StopPlugins then drains each plugin's queue. Reversing - // this order would lose the shutdown event because the webhook's - // bus subscription would be cancelled before doStop publishes. - slog.Info("shutting down") - d.Stop() - - stopCtx, stopCancel := context.WithTimeout(context.Background(), 5*time.Second) - if err := rt.StopPlugins(stopCtx); err != nil { - slog.Warn("plugin shutdown error", "err", err) - } - stopCancel() - if restartRequested { + // Daemon.Stop then StopPlugins (see teardown for why the order + // matters). A daemon-requested exit leaves here via os.Exit with its + // code once the teardown finishes. + shutdown(cause, func() { d.Stop() }, rt.StopPlugins, os.Exit) + if cause.restart { executable, err := os.Executable() if err != nil { slog.Error("resolve daemon executable for remote restart", "err", err) diff --git a/cmd/daemon/shutdown.go b/cmd/daemon/shutdown.go new file mode 100644 index 00000000..caa8a437 --- /dev/null +++ b/cmd/daemon/shutdown.go @@ -0,0 +1,135 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "context" + "log" + "log/slog" + "os" + "syscall" + "time" + + "github.com/pilot-protocol/pilotprotocol/pkg/daemon" +) + +// supervisorExitRequests carries daemon-initiated exits for supervisor +// respawn (the rx watchdog's hard escalation) into main's shutdown loop, +// so they run the same graceful teardown as a signal — above all +// StopPlugins, which terminates the app-store's child apps — before the +// process exits with the requested code. See pkg/daemon/exit.go. +var supervisorExitRequests = make(chan daemon.ExitRequest, 1) + +// forwardExitRequest is the daemon.SetExitHandler hook. Non-blocking, as +// the handler contract requires: a request already pending means the +// shutdown it triggers covers this one too. +func forwardExitRequest(req daemon.ExitRequest) { + select { + case supervisorExitRequests <- req: + default: + } +} + +// shutdownCause records what ended the shutdown loop. +type shutdownCause struct { + // restart: a signed fleet lifecycle command asked for a re-exec. + restart bool + // exit: the daemon asked to exit for supervisor respawn. nil for + // signals and fleet lifecycle requests. + exit *daemon.ExitRequest +} + +// awaitShutdown blocks until something asks the daemon to stop: SIGINT/ +// SIGTERM, a fleet lifecycle request, or a daemon exit request. SIGHUP +// runs onReload and keeps waiting. +func awaitShutdown(sig <-chan os.Signal, lifecycle <-chan string, exits <-chan daemon.ExitRequest, onReload func()) shutdownCause { + for { + select { + case received := <-sig: + if received == syscall.SIGHUP { + onReload() + continue + } + return shutdownCause{} + case l := <-lifecycle: + return shutdownCause{restart: l == "restart"} + case req := <-exits: + return shutdownCause{exit: &req} + } + } +} + +var ( + // daemonStopBudget is how long teardown waits for Daemon.Stop before + // stopping the plugins anyway. Daemon.Stop can hang when the + // transport is wedged — exactly when the rx watchdog asks for an + // exit — and the plugins must still be stopped so the app-store + // reaps its children before the process goes away. + daemonStopBudget = 8 * time.Second + // pluginStopTimeout bounds runtime.StopPlugins. + pluginStopTimeout = 5 * time.Second +) + +// teardown runs the graceful shutdown sequence. +// +// Order matters: Daemon.Stop publishes daemon.shutting_down to the bus +// before tearing down ports/IPC/tunnels. Plugins (notably webhook) are +// still subscribed at that point, so the event flows through. +// StopPlugins then drains each plugin's queue. Reversing this order +// would lose the shutdown event because the webhook's bus subscription +// would be cancelled before doStop publishes. +// +// If Daemon.Stop overruns daemonStopBudget the plugins are stopped +// regardless, then teardown still waits for Daemon.Stop to finish (its +// identity flush runs last). For a supervisor-respawn exit that wait is +// capped by the deadline pkg/daemon armed with the request; for a signal +// it is capped by the supervisor's stop timeout, as before. +func teardown(stopDaemon func(), stopPlugins func(context.Context) error) { + daemonDone := make(chan struct{}) + go func() { + defer close(daemonDone) + stopDaemon() + }() + select { + case <-daemonDone: + case <-time.After(daemonStopBudget): + slog.Warn("daemon stop still running — stopping plugins anyway", + "budget", daemonStopBudget.String()) + } + + stopCtx, stopCancel := context.WithTimeout(context.Background(), pluginStopTimeout) + if err := stopPlugins(stopCtx); err != nil { + slog.Warn("plugin shutdown error", "err", err) + } + stopCancel() + <-daemonDone +} + +// shutdown tears the daemon down and, when the daemon itself asked for +// the exit, exits with its code so launchd (SuccessfulExit=false) and +// systemd (Restart=always) respawn it. Returns for every other cause. +func shutdown(cause shutdownCause, stopDaemon func(), stopPlugins func(context.Context) error, exit func(int)) { + slog.Info("shutting down") + teardown(stopDaemon, stopPlugins) + if cause.exit != nil { + slog.Info("graceful shutdown complete — exiting for supervisor respawn", + "reason", cause.exit.Reason, + "exit_code", cause.exit.Code) + exit(cause.exit.Code) + } +} + +// fatalAfterPluginStart replaces log.Fatalf for failures once plugins are +// running: it stops them before exiting 1. log.Fatalf would skip +// StopPlugins and orphan any app the app-store supervisor had already +// spawned — and since the supervisor respawns on the non-zero exit, a +// persistent startup failure would leak a fresh set on every attempt. +func fatalAfterPluginStart(stopPlugins func(context.Context) error, format string, args ...any) { + log.Printf(format, args...) + stopCtx, stopCancel := context.WithTimeout(context.Background(), pluginStopTimeout) + if err := stopPlugins(stopCtx); err != nil { + log.Printf("plugin shutdown error: %v", err) + } + stopCancel() + os.Exit(1) +} diff --git a/cmd/daemon/shutdown_test.go b/cmd/daemon/shutdown_test.go new file mode 100644 index 00000000..190df136 --- /dev/null +++ b/cmd/daemon/shutdown_test.go @@ -0,0 +1,161 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "context" + "os" + "sync" + "syscall" + "testing" + "time" + + "github.com/pilot-protocol/pilotprotocol/pkg/daemon" +) + +// stepRecorder records teardown steps in the order they ran. +type stepRecorder struct { + mu sync.Mutex + steps []string +} + +func (r *stepRecorder) add(step string) { + r.mu.Lock() + defer r.mu.Unlock() + r.steps = append(r.steps, step) +} + +func (r *stepRecorder) snapshot() []string { + r.mu.Lock() + defer r.mu.Unlock() + return append([]string(nil), r.steps...) +} + +func equalSteps(got, want []string) bool { + if len(got) != len(want) { + return false + } + for i := range got { + if got[i] != want[i] { + return false + } + } + return true +} + +// TestExitRequestRunsGracefulShutdownThenExits: a daemon exit request +// (the rx watchdog's hard escalation) ends the shutdown loop like a +// signal, runs Daemon.Stop then StopPlugins — which reaps the app-store's +// child apps — and only then exits with the requested code. +func TestExitRequestRunsGracefulShutdownThenExits(t *testing.T) { + // Drain anything a previous test left in the package-level channel. + select { + case <-supervisorExitRequests: + default: + } + forwardExitRequest(daemon.ExitRequest{Code: 86, Reason: "rx-wedge"}) + // A second request while one is pending must not block the caller + // (the handler runs on the watchdog goroutine). + forwardExitRequest(daemon.ExitRequest{Code: 1, Reason: "dup"}) + + cause := awaitShutdown(make(chan os.Signal), make(chan string), supervisorExitRequests, func() { + t.Error("reload called without SIGHUP") + }) + if cause.exit == nil || cause.exit.Code != 86 { + t.Fatalf("cause = %+v, want exit request with code 86", cause) + } + if cause.restart { + t.Fatal("exit request must not re-exec") + } + + var rec stepRecorder + exitCode := -1 + shutdown(cause, + func() { rec.add("daemon.Stop") }, + func(context.Context) error { rec.add("StopPlugins"); return nil }, + func(code int) { rec.add("exit"); exitCode = code }) + + if want := []string{"daemon.Stop", "StopPlugins", "exit"}; !equalSteps(rec.snapshot(), want) { + t.Fatalf("teardown steps = %v, want %v", rec.snapshot(), want) + } + if exitCode != 86 { + t.Fatalf("exit code = %d, want 86 (non-zero so the supervisor respawns)", exitCode) + } +} + +// TestSignalShutdownDoesNotExit: SIGTERM keeps the old behavior — tear +// down and return from main (status 0), no forced exit code. +func TestSignalShutdownDoesNotExit(t *testing.T) { + sig := make(chan os.Signal, 2) + sig <- syscall.SIGHUP + sig <- syscall.SIGTERM + reloads := 0 + cause := awaitShutdown(sig, make(chan string), make(chan daemon.ExitRequest), func() { reloads++ }) + if reloads != 1 { + t.Fatalf("SIGHUP reloads = %d, want 1", reloads) + } + if cause.exit != nil || cause.restart { + t.Fatalf("SIGTERM cause = %+v, want plain shutdown", cause) + } + + var rec stepRecorder + shutdown(cause, + func() { rec.add("daemon.Stop") }, + func(context.Context) error { rec.add("StopPlugins"); return nil }, + func(code int) { t.Fatalf("signal shutdown called exit(%d)", code) }) + if want := []string{"daemon.Stop", "StopPlugins"}; !equalSteps(rec.snapshot(), want) { + t.Fatalf("teardown steps = %v, want %v", rec.snapshot(), want) + } +} + +// TestLifecycleRestartCause: the signed fleet restart still maps to a +// re-exec, not an exit. +func TestLifecycleRestartCause(t *testing.T) { + lifecycle := make(chan string, 1) + lifecycle <- "restart" + cause := awaitShutdown(make(chan os.Signal), lifecycle, make(chan daemon.ExitRequest), func() {}) + if !cause.restart || cause.exit != nil { + t.Fatalf("cause = %+v, want restart", cause) + } +} + +// TestTeardownStopsPluginsWhenDaemonStopHangs: a wedged transport can +// hang Daemon.Stop. The plugins must still be stopped once the budget +// runs out, or the app-store's children are orphaned when the exit +// deadline kills the process. +func TestTeardownStopsPluginsWhenDaemonStopHangs(t *testing.T) { + prev := daemonStopBudget + daemonStopBudget = 20 * time.Millisecond + t.Cleanup(func() { daemonStopBudget = prev }) + + release := make(chan struct{}) + pluginsStopped := make(chan struct{}) + done := make(chan struct{}) + var rec stepRecorder + go func() { + defer close(done) + teardown( + func() { <-release; rec.add("daemon.Stop") }, + func(context.Context) error { rec.add("StopPlugins"); close(pluginsStopped); return nil }) + }() + + select { + case <-pluginsStopped: + case <-time.After(5 * time.Second): + t.Fatal("plugins were not stopped while Daemon.Stop hung") + } + select { + case <-done: + t.Fatal("teardown returned before Daemon.Stop finished") + case <-time.After(20 * time.Millisecond): + } + close(release) + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("teardown did not return after Daemon.Stop finished") + } + if want := []string{"StopPlugins", "daemon.Stop"}; !equalSteps(rec.snapshot(), want) { + t.Fatalf("teardown steps = %v, want %v", rec.snapshot(), want) + } +} diff --git a/cmd/pilotctl/main.go b/cmd/pilotctl/main.go index 0dec3553..52edb73b 100644 --- a/cmd/pilotctl/main.go +++ b/cmd/pilotctl/main.go @@ -2993,6 +2993,9 @@ func cmdDaemonStart(args []string) { // Rename the temp log to pilot-{pid}.log. The child's fd follows the // inode, so it continues writing to the same file after the rename. + // The daemon's log cap finishes a dead daemon's interrupted rotation + // only under this name (internal/logcap isDaemonStartLog): keep the + // two in step. pidLogPath := configDir() + "/pilot-" + strconv.Itoa(pid) + ".log" logFile.Close() os.Rename(tmpLogPath, pidLogPath) diff --git a/internal/logcap/fdpath_darwin.go b/internal/logcap/fdpath_darwin.go new file mode 100644 index 00000000..fd0e6146 --- /dev/null +++ b/internal/logcap/fdpath_darwin.go @@ -0,0 +1,40 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build darwin + +package logcap + +import ( + "bytes" + "os" + "sync" + "unsafe" + + "golang.org/x/sys/unix" +) + +const fdPathSupported = true + +// getpathBuf receives F_GETPATH's result. The buffer's address reaches +// fcntl as a plain integer, which the runtime neither tracks nor fixes up +// if a stack-allocated buffer moved, so it lives in static storage. +var ( + getpathMu sync.Mutex + getpathBuf [unix.PathMax]byte +) + +// fdPath returns the current path of the file open on f (fcntl F_GETPATH). +// It follows renames of the open file. +func fdPath(f *os.File) (string, error) { + getpathMu.Lock() + defer getpathMu.Unlock() + // #nosec G103 -- F_GETPATH takes a MAXPATHLEN output buffer by address. + if _, err := unix.FcntlInt(f.Fd(), unix.F_GETPATH, int(uintptr(unsafe.Pointer(&getpathBuf[0])))); err != nil { + return "", err + } + n := bytes.IndexByte(getpathBuf[:], 0) + if n < 0 { + n = len(getpathBuf) + } + return string(getpathBuf[:n]), nil +} diff --git a/internal/logcap/fdpath_linux.go b/internal/logcap/fdpath_linux.go new file mode 100644 index 00000000..1c1ae1ba --- /dev/null +++ b/internal/logcap/fdpath_linux.go @@ -0,0 +1,19 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build linux + +package logcap + +import ( + "os" + "strconv" +) + +const fdPathSupported = true + +// fdPath returns the current path of the file open on f via +// /proc/self/fd. A deleted file reads back as " (deleted)", which +// the caller's same-file check then rejects. +func fdPath(f *os.File) (string, error) { + return os.Readlink("/proc/self/fd/" + strconv.FormatUint(uint64(f.Fd()), 10)) +} diff --git a/internal/logcap/fdpath_other.go b/internal/logcap/fdpath_other.go new file mode 100644 index 00000000..a0696b85 --- /dev/null +++ b/internal/logcap/fdpath_other.go @@ -0,0 +1,18 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build !darwin && !linux + +package logcap + +import ( + "errors" + "os" +) + +// fdPathSupported is false here: without a path there is no backup, so +// Watch leaves the log alone rather than truncate it blind. +const fdPathSupported = false + +func fdPath(*os.File) (string, error) { + return "", errors.New("logcap: mapping a descriptor to its path is unsupported on this platform") +} diff --git a/internal/logcap/group.go b/internal/logcap/group.go new file mode 100644 index 00000000..9568c11c --- /dev/null +++ b/internal/logcap/group.go @@ -0,0 +1,99 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import ( + "strconv" + "strings" +) + +// userPrivateGroup reports whether gid is uid's user private group, going +// by passwd and group, the contents of /etc/passwd and /etc/group: the +// primary group of uid's account, with the account's name, and no other +// member — no other account has it as its primary group and the group +// lists no one else. +// +// That is the user-private-group scheme of Debian/Ubuntu and Fedora/RHEL +// (useradd's USERGROUPS_ENAB), under which the login umask is 002 — RHEL's +// /etc/bashrc applies it on the same test, group name equal to user name — +// so the user's directories, ~/.pilot among them, are group-writable with +// a group no one else is in. The name check keeps out a shared group such +// as "users" that the account happens to be the only member of so far. +// +// Anything else counts as shared: an account or group missing from the +// files (from LDAP, say), a line it cannot parse, and a NIS compat entry +// ("+..." or "-..."), which pulls in accounts from elsewhere. +func userPrivateGroup(uid, gid int, passwd, group []byte) bool { + users, ok := dbEntries(passwd, 7) + if !ok { + return false + } + name := "" + for _, f := range users { + u, uerr := strconv.Atoi(f[2]) + g, gerr := strconv.Atoi(f[3]) + if uerr != nil || gerr != nil { + return false + } + switch { + case u == uid && name == "": + // The first entry is the one getpwuid returns. + if g != gid { + return false + } + name = f[0] + case u != uid && g == gid: + return false // another account's primary group + } + } + if name == "" { + return false + } + + groups, ok := dbEntries(group, 4) + if !ok { + return false + } + found := false + for _, f := range groups { + g, err := strconv.Atoi(f[2]) + if err != nil { + return false + } + if g != gid { + continue + } + if f[0] != name { + return false + } + for _, m := range strings.Split(f[3], ",") { + if m != "" && m != name { + return false + } + } + found = true + } + return found +} + +// dbEntries splits the lines of a passwd- or group-format file into their +// colon-separated fields, skipping blank lines and comments. It fails on +// a line without exactly n fields and on a NIS compat entry. +func dbEntries(data []byte, n int) ([][]string, bool) { + var entries [][]string + for _, line := range strings.Split(string(data), "\n") { + line = strings.TrimSpace(line) + if line == "" || strings.HasPrefix(line, "#") { + continue + } + if strings.HasPrefix(line, "+") || strings.HasPrefix(line, "-") { + return nil, false + } + f := strings.Split(line, ":") + if len(f) != n { + return nil, false + } + entries = append(entries, f) + } + return entries, true +} diff --git a/internal/logcap/group_linux.go b/internal/logcap/group_linux.go new file mode 100644 index 00000000..522d9710 --- /dev/null +++ b/internal/logcap/group_linux.go @@ -0,0 +1,48 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build linux + +package logcap + +import ( + "errors" + "os" + "syscall" +) + +// privateGroupDir reports whether only this user can write to dir (whose +// Lstat is fi) through its group permission: the directory's group is +// the user's private group (userPrivateGroup) and it has no POSIX ACL. +// With an ACL the group bits are the ACL's mask, and a named user or +// group entry may hold the write they show. +func privateGroupDir(dir string, fi os.FileInfo) bool { + st, ok := fi.Sys().(*syscall.Stat_t) + if !ok { + return false + } + if acl, err := hasAccessACL(dir); err != nil || acl { + return false + } + passwd, err := os.ReadFile("/etc/passwd") + if err != nil { + return false + } + group, err := os.ReadFile("/etc/group") + if err != nil { + return false + } + return userPrivateGroup(os.Geteuid(), int(st.Gid), passwd, group) +} + +// hasAccessACL reports whether dir carries a POSIX access ACL. The kernel +// stores none for an ACL the mode bits already express. +func hasAccessACL(dir string) (bool, error) { + _, err := syscall.Getxattr(dir, "system.posix_acl_access", nil) + switch { + case err == nil: + return true, nil + case errors.Is(err, syscall.ENODATA), errors.Is(err, syscall.ENOTSUP): + return false, nil + } + return false, err +} diff --git a/internal/logcap/group_linux_test.go b/internal/logcap/group_linux_test.go new file mode 100644 index 00000000..216a62ed --- /dev/null +++ b/internal/logcap/group_linux_test.go @@ -0,0 +1,126 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build linux + +package logcap + +import ( + "encoding/binary" + "errors" + "os" + "path/filepath" + "strings" + "syscall" + "testing" +) + +// umask002Dir makes a directory the way `mkdir -p ~/.pilot/bin` does in +// install.sh under umask 002 — group-writable, with the process's group — +// and skips the test unless that group is this user's private group in +// /etc/passwd and /etc/group (the linux container run creates such a +// user). +func umask002Dir(t *testing.T) string { + t.Helper() + passwd, perr := os.ReadFile("/etc/passwd") + group, gerr := os.ReadFile("/etc/group") + if perr != nil || gerr != nil || !userPrivateGroup(os.Geteuid(), os.Getegid(), passwd, group) { + t.Skip("this user's primary group is not a user private group") + } + dir := filepath.Join(t.TempDir(), ".pilot") + old := syscall.Umask(0o002) + err := os.Mkdir(dir, 0o777) + syscall.Umask(old) + if err != nil { + t.Fatal(err) + } + fi, err := os.Lstat(dir) + if err != nil { + t.Fatal(err) + } + if fi.Mode().Perm() != 0o775 { + t.Fatalf("mode %v, want 0775", fi.Mode().Perm()) + } + if gid := fi.Sys().(*syscall.Stat_t).Gid; int(gid) != os.Getegid() { + t.Skipf("directory got group %d, not the process's (setgid parent)", gid) + } + return dir +} + +// TestCheckRealPrivateGroupDirectory: with the real account files, a log +// in a directory made under umask 002 by a user with a private group is +// rotated with backups. +func TestCheckRealPrivateGroupDirectory(t *testing.T) { + dir := umask002Dir(t) + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + content := strings.Repeat("u", 50) + write(t, f, content) + mustRotate(t, New(f, Options{MaxBytes: 10, MaxBackups: 3, Within: []string{dir}})) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("backup = %q, want the log", got) + } +} + +// TestPrivateGroupDirWithACL: a POSIX ACL entry can give another user the +// write the group bits (then the ACL mask) show, so a directory with one +// is not taken as private. +func TestPrivateGroupDirWithACL(t *testing.T) { + dir := umask002Dir(t) + fi, err := os.Lstat(dir) + if err != nil { + t.Fatal(err) + } + if !privateGroupDir(dir, fi) { + t.Fatal("private group directory without an ACL was not accepted") + } + + // user::rwx user:4242:rwx group::rwx mask::rwx other::r-x, in the + // kernel's system.posix_acl_access format. + const undefined = 0xffffffff + acl := binary.LittleEndian.AppendUint32(nil, 2) + for _, e := range []struct { + tag, perm uint16 + id uint32 + }{ + {0x01, 7, undefined}, + {0x02, 7, uint32(foreignUID)}, + {0x04, 7, undefined}, + {0x10, 7, undefined}, + {0x20, 5, undefined}, + } { + acl = binary.LittleEndian.AppendUint16(acl, e.tag) + acl = binary.LittleEndian.AppendUint16(acl, e.perm) + acl = binary.LittleEndian.AppendUint32(acl, e.id) + } + if err := syscall.Setxattr(dir, "system.posix_acl_access", acl, 0); err != nil { + if errors.Is(err, syscall.ENOTSUP) { + t.Skip("filesystem has no POSIX ACLs") + } + t.Fatal(err) + } + fi, err = os.Lstat(dir) + if err != nil { + t.Fatal(err) + } + if privateGroupDir(dir, fi) { + t.Fatal("directory with an ACL granting another user write was taken as private") + } + if err := checkDir(dir); err == nil { + t.Fatal("checkDir accepted a directory another user can write through an ACL") + } +} + +// TestPrivateGroupDirOtherGroup: a group-writable directory whose group +// is not the user's is not private (needs root to chgrp). +func TestPrivateGroupDirOtherGroup(t *testing.T) { + if os.Geteuid() != 0 { + t.Skip("needs root to give the directory another group") + } + dir := umask002Dir(t) + if err := os.Chown(dir, -1, foreignUID); err != nil { + t.Fatal(err) + } + if err := checkDir(dir); err == nil { + t.Fatal("checkDir accepted a directory writable by another group") + } +} diff --git a/internal/logcap/group_other.go b/internal/logcap/group_other.go new file mode 100644 index 00000000..b54a47c9 --- /dev/null +++ b/internal/logcap/group_other.go @@ -0,0 +1,14 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build !linux + +package logcap + +import "os" + +// privateGroupDir is false: a group-writable log directory keeps no +// backups. macOS has no user private groups — a user's primary group is +// staff, shared by every local account — and its /etc/passwd and +// /etc/group are not where its accounts live. Rotation does not run on +// the other platforms (fdPathSupported is false). +func privateGroupDir(string, os.FileInfo) bool { return false } diff --git a/internal/logcap/group_test.go b/internal/logcap/group_test.go new file mode 100644 index 00000000..eff1d89f --- /dev/null +++ b/internal/logcap/group_test.go @@ -0,0 +1,59 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import "testing" + +// TestUserPrivateGroup: only a group that is the account's primary group, +// named after it and with no one else in it counts as private; anything +// the files do not show to be that counts as shared. +func TestUserPrivateGroup(t *testing.T) { + const passwd = `# comment +root:x:0:0:root:/root:/bin/bash +daemon:x:1:1:daemon:/usr/sbin:/usr/sbin/nologin + +alice:x:1000:1000:Alice:/home/alice:/bin/bash +bob:x:1001:1001:Bob:/home/bob:/bin/bash +carol:x:1002:100:Carol:/home/carol:/bin/bash +` + const group = `root:x:0: +daemon:x:1: +users:x:100: +alice:x:1000: +bob:x:1001: +` + for _, tc := range []struct { + name string + uid, gid int + passwd, group string + want bool + }{ + {"private group", 1000, 1000, passwd, group, true}, + {"root's group", 0, 0, passwd, group, true}, + {"lists the user itself", 1000, 1000, passwd, "alice:x:1000:alice\n", true}, + {"another user's group", 1000, 1001, passwd, group, false}, + {"not the primary group", 1000, 100, passwd, group, false}, + {"named after the user, not its primary", 1000, 2000, passwd, "alice:x:2000:\n", false}, + {"shared group, one member so far", 1002, 100, passwd, group, false}, + {"another member listed", 1000, 1000, passwd, "alice:x:1000:alice,bob\n", false}, + {"another account's primary group", 1000, 1000, + passwd + "dave:x:1003:1000::/home/dave:/bin/sh\n", group, false}, + {"duplicate entry with a member", 1000, 1000, passwd, + group + "alice:x:1000:bob\n", false}, + {"differently named", 1000, 1000, passwd, "staff:x:1000:\n", false}, + {"group missing", 1000, 1000, passwd, "root:x:0:\n", false}, + {"account missing", 1005, 1005, passwd, "eve:x:1005:\n", false}, + {"NIS compat in passwd", 1000, 1000, passwd + "+::::::\n", group, false}, + {"NIS compat in group", 1000, 1000, passwd, group + "+:::\n", false}, + {"malformed passwd", 1000, 1000, passwd + "broken:x:12\n", group, false}, + {"malformed group", 1000, 1000, passwd, group + "broken:x\n", false}, + {"non-numeric gid", 1000, 1000, passwd + "frank:x:1004:abc::/:/bin/sh\n", group, false}, + {"empty files", 1000, 1000, "", "", false}, + } { + t.Run(tc.name, func(t *testing.T) { + if got := userPrivateGroup(tc.uid, tc.gid, []byte(tc.passwd), []byte(tc.group)); got != tc.want { + t.Fatalf("userPrivateGroup(%d, %d) = %v, want %v", tc.uid, tc.gid, got, tc.want) + } + }) + } +} diff --git a/internal/logcap/lock_other.go b/internal/logcap/lock_other.go new file mode 100644 index 00000000..89d0dd91 --- /dev/null +++ b/internal/logcap/lock_other.go @@ -0,0 +1,16 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build !darwin && !linux + +package logcap + +import ( + "errors" + "os" +) + +// Rotation never runs here (fdPathSupported is false); this only keeps +// the package building. +func flock(*os.File) error { + return errors.New("logcap: file locking is unsupported on this platform") +} diff --git a/internal/logcap/lock_unix.go b/internal/logcap/lock_unix.go new file mode 100644 index 00000000..b8f5ff03 --- /dev/null +++ b/internal/logcap/lock_unix.go @@ -0,0 +1,38 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build darwin || linux + +package logcap + +import ( + "errors" + "os" + "syscall" +) + +// flock takes an exclusive flock(2) on f without waiting. The lock +// belongs to f's open file description and goes away when it is closed, +// including when the process dies, so a copy left locked by a crash is +// free again. It returns errBusy when another open file description +// holds the lock, and another error when the filesystem cannot lock. +func flock(f *os.File) error { + rc, err := f.SyscallConn() + if err != nil { + return err + } + var lockErr error + if err := rc.Control(func(fd uintptr) { + for { + lockErr = syscall.Flock(int(fd), syscall.LOCK_EX|syscall.LOCK_NB) + if !errors.Is(lockErr, syscall.EINTR) { + return + } + } + }); err != nil { + return err + } + if errors.Is(lockErr, syscall.EWOULDBLOCK) { + return errBusy + } + return lockErr +} diff --git a/internal/logcap/logcap.go b/internal/logcap/logcap.go new file mode 100644 index 00000000..7ec611e2 --- /dev/null +++ b/internal/logcap/logcap.go @@ -0,0 +1,804 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +// Package logcap caps the size of the daemon's own log file. +// +// Under launchd the daemon's stdout/stderr are a plain file +// (StandardOutPath/StandardErrorPath = ~/.pilot/daemon.log) that launchd +// opens and never rotates, and nothing else is set up to: one laptop's +// daemon.log reached 22 MB, a June log 13 MB compressed. Renaming it away +// would not help — the daemon, and every child it spawns (they inherit +// the descriptor), keep writing to the open file. +// +// So the daemon rotates it from the inside, copy-truncate style: when +// the file exceeds the limit, copy it to .pilot.1, truncate the +// original through the daemon's own descriptor, then gzip the copy into +// .pilot.1.gz, shifting older generations up to .pilot.N.gz. +// Truncation is safe for every writer: launchd (and `pilotctl daemon +// start`) open the log O_APPEND, so each write lands at the new end of +// file, and children share that same open file description. Lines +// written between the copy and the truncate are lost — the usual +// copy-truncate trade-off, a window of milliseconds. +// +// The oldest generation is dropped only once the log is truncated. A log +// that cannot be truncated (an append-only file, a filesystem that +// refuses it) keeps all its generations: the copy is removed and the +// shift undone, and the daemon retries at growing intervals rather than +// copying the whole log every minute. +// +// Files logcap did not create are left alone. The ".pilot" infix keeps +// its names apart from the ones other rotators give the same log +// (logrotate's .1 and .N.gz, newsyslog's .0.gz), so an +// operator's own rotation keeps its history. Within its own names, +// logcap reads back, renames or removes only a regular file owned by +// the current user; a symlink, a directory or another user's file at +// one of them stops that round's backup (the log is still truncated). +// Files are created O_EXCL|O_NOFOLLOW, never through an existing name. +// When the log's directory is writable by others, or by a group other +// than the user's own private group, or owned by another user (not +// root), logcap keeps no backups at all and only truncates, so it +// creates nothing where someone else could have planted a link. +// +// A rotation that dies between the copy and the compress (crash, kill) +// leaves .pilot.1 behind; the next rotation of that log finishes +// it. `pilotctl daemon start` names each daemon's log pilot-.log, +// so no later daemon rotates the name a crashed one staged under: a +// rotation in the directory `pilotctl daemon start` uses (one of +// Options.Within, not a directory below it) also finishes the copies of +// those logs, pilot-.log.pilot.1. It takes no other .pilot.1 +// for an interrupted copy: that may be another program's file, such as +// logrotate's delaycompress generation of a log named .pilot. A +// rotation holds its staged copy flock(2)ed from creation until it is +// compressed, which is how a copy another live daemon is still working +// on is told apart and left alone. +// +// Options.Anywhere, Options.Within and Options.Files set where it +// applies: the daemon rotates by default only a log Pilot set up — +// inside ~/.pilot, where install.sh's launchd job and `pilotctl daemon +// start` put it, or the Homebrew service's log — and a log elsewhere +// only when the operator asks for rotation explicitly. +// +// When the log is not a regular file — journald under systemd, a +// terminal, a pipe — there is nothing to cap and the package does +// nothing. +package logcap + +import ( + "compress/gzip" + "context" + "errors" + "fmt" + "io" + "io/fs" + "log/slog" + "os" + "path/filepath" + "strings" + "time" +) + +// Options configure a Rotator. +type Options struct { + // MaxBytes is the size past which the log is rotated; <= 0 disables + // rotation. + MaxBytes int64 + // MaxBackups is the number of gzipped generations kept; 0 truncates + // without keeping any. + MaxBackups int + // Anywhere rotates the log wherever it lives. Without it only a log + // inside one of the Within directories (at any depth), or at one of + // the Files paths, is rotated, so the zero Options rotate nothing. + Anywhere bool + // Within are Pilot's own directories. A rotation of a log directly in + // one of them, with or without Anywhere, also finishes the + // interrupted rotations of `pilotctl daemon start`'s logs there. + Within []string + // Files are single logs in scope in a directory that is not Pilot's + // as a whole, such as the Homebrew service's + // /var/log/pilot-daemon.log. A log matches one by name within + // the same directory, the directory compared by identity. + Files []string +} + +// Rotator caps one log file, identified by the descriptor the process +// writes it through (os.Stderr in the daemon). +type Rotator struct { + file *os.File + maxBytes int64 + maxBackups int + anywhere bool + within []string + files []string + + // truncateFailures counts the rounds in a row, up to now, in which + // the log could not be truncated (tick). + truncateFailures int +} + +// New returns a Rotator that rotates f once it exceeds opts.MaxBytes. +func New(f *os.File, opts Options) *Rotator { + backups := opts.MaxBackups + if backups < 0 { + backups = 0 + } + return &Rotator{ + file: f, + maxBytes: opts.MaxBytes, + maxBackups: backups, + anywhere: opts.Anywhere, + within: opts.Within, + files: opts.Files, + } +} + +// errOutOfScope reports a log outside the places rotation is limited to +// (Options.Within, Options.Files). +var errOutOfScope = errors.New("log is outside the directories rotation is limited to") + +// errBusy reports a staged copy that another rotation holds locked: one +// still in progress, in this process or another. +var errBusy = errors.New("staged copy is in use by another rotation") + +// errTruncate reports a log that could not be truncated. Nothing was +// rotated, and run retries at growing intervals (retryAfter). +var errTruncate = errors.New("truncate log") + +// maxRetryDoublings caps retryAfter at 2^6 = 64 intervals, about an hour +// at the daemon's one-minute interval. +const maxRetryDoublings = 6 + +// Watch checks f every interval until ctx is done, rotating it whenever it +// has grown past opts.MaxBytes; less often while f cannot be truncated +// (retryAfter). It returns false, starting nothing, when +// capping is disabled (MaxBytes <= 0), f is not a regular file, the +// platform cannot map a descriptor back to its path, or the log is out of +// scope (see Options.Anywhere). +func Watch(ctx context.Context, f *os.File, opts Options, interval time.Duration) bool { + if opts.MaxBytes <= 0 || !fdPathSupported { + return false + } + fi, err := f.Stat() + if err != nil || !fi.Mode().IsRegular() { + return false + } + r := New(f, opts) + if !r.anywhere { + path, err := fdPath(f) + if err != nil || !namesFile(path, fi) || !r.inScope(path) { + return false + } + } + go r.run(ctx, interval) + return true +} + +func (r *Rotator) run(ctx context.Context, interval time.Duration) { + for { + // Check first so a log already over the limit at startup is + // rotated right away rather than an interval later. + wait, ok := r.tick(interval) + if !ok { + return + } + timer := time.NewTimer(wait) + select { + case <-ctx.Done(): + timer.Stop() + return + case <-timer.C: + } + } +} + +// tick runs one Check and logs its outcome. It returns how long to wait +// before the next one, or false once rotation has stopped for good. +func (r *Rotator) tick(interval time.Duration) (time.Duration, bool) { + rotated, err := r.Check() + if !errors.Is(err, errTruncate) { + r.truncateFailures = 0 + } + switch { + case err == nil: + case errors.Is(err, errOutOfScope): + // Moved out of the pilot directory: someone else's log now. + slog.Info("log rotation stopped", "reason", err) + return 0, false + case rotated: + slog.Warn("log truncated without keeping a backup", "err", err) + case errors.Is(err, errTruncate): + r.truncateFailures++ + wait := retryAfter(interval, r.truncateFailures) + slog.Warn("log rotation failed", "err", err, "retry_in", wait) + return wait, true + default: + slog.Warn("log rotation failed", "err", err) + } + return interval, true +} + +// retryAfter is the wait after the log could not be truncated failures +// rounds in a row. Each such round copies the whole log for nothing, so +// the wait doubles with every failure: 1, 2, 4 … up to 64 intervals. +func retryAfter(interval time.Duration, failures int) time.Duration { + return interval << min(max(failures-1, 0), maxRetryDoublings) +} + +// Check rotates the log if it has grown past the limit and reports +// whether it did. A non-nil error with rotated == true means the log was +// truncated but its backup could not be kept. +func (r *Rotator) Check() (rotated bool, err error) { + fi, err := r.file.Stat() + if err != nil { + return false, err + } + if !fi.Mode().IsRegular() || fi.Size() <= r.maxBytes { + return false, nil + } + return r.rotate(fi) +} + +func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { + var backupErr error + path, src, err := r.openByPath(fi) + if err != nil { + // No readable path for the log (deleted, or not openable by + // name): still truncate — capping disk use is the point — + // without a backup. fdPath follows renames, so a log moved out of + // scope still resolves, and is caught below. + backupErr = err + } else if !r.inScope(path) { + _ = src.Close() + return false, fmt.Errorf("%w: %s", errOutOfScope, path) + } + + var staged *os.File + var parked bool + if src != nil { + if r.maxBackups > 0 { + staged, parked, backupErr = stage(src, path, r.maxBackups) + } + _ = src.Close() + } + if staged != nil { + // Closing it releases the lock that marks the copy as in use. + defer staged.Close() + } + + if err := truncate(r.file); err != nil { + err = fmt.Errorf("%w: %w", errTruncate, err) + if staged != nil { + err = errors.Join(err, unstage(path, r.maxBackups, parked)) + } + return false, err + } + + backup := "" + if staged != nil { + dropParked(path, r.maxBackups, parked) + backup = backupName(path, 1) + if err := compress(staged.Name(), backup); err != nil { + backupErr = fmt.Errorf("compress %s: %w", staged.Name(), err) + backup = "" + } + } + slog.Info("log rotated", + "path", path, + "size_bytes", fi.Size(), + "max_bytes", r.maxBytes, + "backup", backup) + if staged != nil && r.isWithinDir(filepath.Dir(path)) { + // After this log's own rotation, so the log is capped first. + finishOrphans(path) + } + return true, backupErr +} + +// unstage undoes stage after the log could not be truncated: this round +// keeps no backup, so nothing moves. It removes the copy, which also +// keeps the next round from compressing a duplicate, and then moves the +// generations back down. A copy it cannot remove stays for a later round +// to finish into generation 1, which is left free for it. +func unstage(path string, keep int, parked bool) error { + if err := os.Remove(stagingName(path)); err != nil && !errors.Is(err, fs.ErrNotExist) { + dropParked(path, keep, parked) + return fmt.Errorf("remove copy of a log not truncated: %w", err) + } + if err := unshiftBackups(path, keep, parked); err != nil { + return fmt.Errorf("restore backups: %w", err) + } + return nil +} + +// openByPath opens the log for reading via its path — the write-only +// descriptor the process holds cannot be read — and confirms the path +// still names the same file. O_NOFOLLOW plus the same-file check mean it +// only ever reads the file this descriptor writes. +func (r *Rotator) openByPath(fi os.FileInfo) (string, *os.File, error) { + path, err := fdPath(r.file) + if err != nil { + return "", nil, fmt.Errorf("resolve log path: %w", err) + } + // #nosec G304 -- path is resolved from the daemon's own stderr + // descriptor, not from any peer or user input. + src, err := os.OpenFile(path, os.O_RDONLY|oNoFollow, 0) + if err != nil { + return path, nil, err + } + sfi, err := src.Stat() + if err != nil || !os.SameFile(fi, sfi) { + _ = src.Close() + return path, nil, fmt.Errorf("%s no longer names the open log file", path) + } + return path, src, nil +} + +// namesFile reports whether path (not following a final symlink) is fi. +func namesFile(path string, fi os.FileInfo) bool { + pfi, err := os.Lstat(path) + return err == nil && os.SameFile(fi, pfi) +} + +// isWithinDir reports whether dir is one of r.within itself (not a +// directory below it), compared by identity: where `pilotctl daemon +// start` puts each daemon's log. +func (r *Rotator) isWithinDir(dir string) bool { + fi, err := os.Stat(dir) + if err != nil { + return false + } + for _, d := range r.within { + if wfi, err := os.Stat(d); err == nil && os.SameFile(fi, wfi) { + return true + } + } + return false +} + +// inScope reports whether path is one of r.files or lies inside one of +// r.within. Directories are compared by identity, so a symlinked +// ~/.pilot, or /var against macOS's /private/var, still matches. +func (r *Rotator) inScope(path string) bool { + if r.anywhere || r.isScopedFile(path) { + return true + } + var roots []os.FileInfo + for _, d := range r.within { + if fi, err := os.Stat(d); err == nil && fi.IsDir() { + roots = append(roots, fi) + } + } + if len(roots) == 0 { + return false + } + dir := filepath.Dir(path) + for { + if fi, err := os.Stat(dir); err == nil { + for _, root := range roots { + if os.SameFile(fi, root) { + return true + } + } + } + parent := filepath.Dir(dir) + if parent == dir { + return false + } + dir = parent + } +} + +// isScopedFile reports whether path is one of r.files: the same name in +// the same directory, compared by identity. +func (r *Rotator) isScopedFile(path string) bool { + var dir os.FileInfo + for _, f := range r.files { + if filepath.Base(f) != filepath.Base(path) { + continue + } + if dir == nil { + fi, err := os.Stat(filepath.Dir(path)) + if err != nil { + return false + } + dir = fi + } + if fi, err := os.Stat(filepath.Dir(f)); err == nil && os.SameFile(fi, dir) { + return true + } + } + return false +} + +// stage prepares this round's backup: it finishes an interrupted +// rotation, shifts the older generations up and copies the log (src, +// open at offset 0) to .pilot.1, which it returns open and locked +// for the caller to close once it is compressed. The oldest generation +// is parked rather than dropped (parked reports whether there was one): +// the caller drops it once the log is truncated (dropParked), or undoes +// the round if it cannot be (unstage). An error means no backup is kept +// this round; nothing has moved when the interrupted rotation could not +// be finished. +func stage(src *os.File, path string, keep int) (held *os.File, parked bool, err error) { + if err := checkDir(filepath.Dir(path)); err != nil { + return nil, false, fmt.Errorf("keeping no backup: %w", err) + } + if err := finishStaged(path, false); err != nil { + return nil, false, fmt.Errorf("keeping no backup: finish interrupted rotation %s: %w", stagingName(path), err) + } + parked, err = shiftBackups(path, keep) + if err != nil { + dropParked(path, keep, parked) + return nil, false, fmt.Errorf("keeping no backup: %w", err) + } + staged := stagingName(path) + held, err = createStaged(src, staged) + if err != nil { + dropParked(path, keep, parked) + return nil, false, fmt.Errorf("copy log to %s: %w", staged, err) + } + return held, parked, nil +} + +// truncate empties the log through the writer's own descriptor. +// +// Rewind first: a writer without O_APPEND (a shell's `2>file`) shares this +// offset, and left at the old end its next write would recreate the old +// size as a sparse hole. O_APPEND writers ignore the offset. Rewinding +// BEFORE truncating means a write racing in between lands at offset 0 and +// is then cut, rather than landing past the new end of file. +func truncate(f *os.File) error { + if _, err := f.Seek(0, io.SeekStart); err != nil { + return err + } + return f.Truncate(0) +} + +// backupName is generation gen's name. The ".pilot" infix keeps it apart +// from the names another rotator gives the same log. +func backupName(path string, gen int) string { + return fmt.Sprintf("%s.pilot.%d.gz", path, gen) +} + +// stagingSuffix names the uncompressed copy a rotation gzips into +// generation 1. +const stagingSuffix = ".pilot.1" + +// stagingName is the uncompressed copy a rotation gzips into generation 1. +func stagingName(path string) string { + return path + stagingSuffix +} + +// ownerOf is fileOwner; tests swap it to simulate another user's files. +var ownerOf = fileOwner + +// tryLock is flock; tests swap it to simulate a filesystem without locks. +var tryLock = flock + +// groupIsPrivate is privateGroupDir; tests swap it to simulate a +// directory's group being, or not being, the user's private group. +var groupIsPrivate = privateGroupDir + +// ours reports whether fi is a regular file owned by this process's user, +// the only kind of file logcap reads back, renames or removes. +func ours(fi os.FileInfo) bool { + if !fi.Mode().IsRegular() { + return false + } + uid, ok := ownerOf(fi) + return ok && uid == os.Geteuid() +} + +// lookup reports whether name exists, and fails when it holds something +// logcap must not touch: a symlink, a directory, another user's file. +func lookup(name string) (bool, error) { + fi, err := os.Lstat(name) + if errors.Is(err, fs.ErrNotExist) { + return false, nil + } + if err != nil { + return false, err + } + if !ours(fi) { + return true, fmt.Errorf("%s is not a regular file owned by this user; leaving it alone", name) + } + return true, nil +} + +// openOurs opens name for reading, without following a symlink, and only +// if it is a regular file owned by this user. +func openOurs(name string) (*os.File, error) { + // #nosec G304 -- name is derived from the daemon's own log path. + f, err := os.OpenFile(name, os.O_RDONLY|oNoFollow, 0) + if err != nil { + return nil, err + } + fi, err := f.Stat() + if err == nil && !ours(fi) { + err = fmt.Errorf("%s is not a regular file owned by this user; leaving it alone", name) + } + if err != nil { + _ = f.Close() + return nil, err + } + return f, nil +} + +// checkDir refuses a directory where another user could have planted a +// link or a file at one of logcap's names: one writable by others — a +// sticky /tmp included, as the sticky bit stops removing others' names, +// not creating new ones — or by a group other users may be in, or one +// owned by another user (root excepted). +// +// A group-writable directory is accepted when its group is the user's +// own private group (privateGroupDir): with user private groups, the +// default on Debian/Ubuntu and Fedora/RHEL, the login umask 002 makes +// ~/.pilot group-writable with a group no one else is in. +func checkDir(dir string) error { + fi, err := os.Lstat(dir) + if err != nil { + return err + } + if !fi.IsDir() { + return fmt.Errorf("%s is not a directory", dir) + } + if fi.Mode().Perm()&0o002 != 0 { + return fmt.Errorf("log directory %s is writable by others", dir) + } + if uid, ok := ownerOf(fi); !ok || (uid != os.Geteuid() && uid != 0) { + return fmt.Errorf("log directory %s is owned by another user", dir) + } + if fi.Mode().Perm()&0o020 != 0 && !groupIsPrivate(dir, fi) { + return fmt.Errorf("log directory %s is writable by a group other users may be in", dir) + } + return nil +} + +// shiftBackups frees the .pilot.1.gz slot: each generation moves up +// by one. The oldest, generation keep, is not dropped yet but parked at +// keep+1 (parked reports whether it existed), so that unshiftBackups can +// put everything back until the log is truncated; dropParked then drops +// it. Generations beyond keep (left from a larger -log-max-backups, or a +// round that died with one parked) are removed first, up to the first +// gap. Every slot up to keep+1 is checked before anything moves, so a +// name holding something that is not ours stops the shift with the +// generations intact. +func shiftBackups(path string, keep int) (parked bool, err error) { + for gen := 1; gen <= keep+1; gen++ { + if _, err := lookup(backupName(path, gen)); err != nil { + return false, err + } + } + for gen := keep + 1; ; gen++ { + name := backupName(path, gen) + if exists, err := lookup(name); err != nil || !exists { + break + } + if err := os.Remove(name); err != nil { + break + } + } + for gen := keep; gen >= 1; gen-- { + err := os.Rename(backupName(path, gen), backupName(path, gen+1)) + switch { + case err == nil: + parked = parked || gen == keep + case !errors.Is(err, fs.ErrNotExist): + return parked, err + } + } + return parked, nil +} + +// unshiftBackups undoes a completed shiftBackups: each generation moves +// back down by one, the parked one included. +func unshiftBackups(path string, keep int, parked bool) error { + top := keep + if parked { + top = keep + 1 + } + for gen := 2; gen <= top; gen++ { + err := os.Rename(backupName(path, gen), backupName(path, gen-1)) + if err != nil && !errors.Is(err, fs.ErrNotExist) { + return err + } + } + return nil +} + +// dropParked removes the generation shiftBackups parked, if it parked one. +func dropParked(path string, keep int, parked bool) { + if parked { + _ = os.Remove(backupName(path, keep+1)) + } +} + +// finishStaged compresses .pilot.1, a copy left by a rotation that +// stopped between the copy and the compress (crash, kill), into +// .pilot.1.gz. That slot is free: the shift that preceded the copy +// already moved the old generation 1 up. When it cannot, the copy stays +// where it is for a later round. A copy a rotation still holds locked is +// in progress, not interrupted: it is left alone and errBusy returned. +// +// For another log's copy (orphan, see finishOrphans) it also leaves alone +// an empty copy, which a live rotation may have created and not yet +// locked, and does nothing where the filesystem has no flock, as it then +// cannot tell a dead rotation's copy from a live one's. +func finishStaged(log string, orphan bool) error { + staged := stagingName(log) + exists, err := lookup(staged) + if err != nil || !exists { + return err + } + f, err := openOurs(staged) + if err != nil { + return err + } + defer f.Close() + fi, err := f.Stat() + if err != nil { + return err + } + if orphan && fi.Size() == 0 { + return nil + } + switch err := tryLock(f); { + case err == nil: + case errors.Is(err, errBusy): + return err + case orphan: + return nil + } + // A rotation that held the lock until just now removed the name when + // it finished; what is there now, if anything, is a new copy. + if !namesFile(staged, fi) { + return errBusy + } + return compress(staged, backupName(log, 1)) +} + +// finishOrphans finishes the interrupted rotations of the other +// daemons' logs in path's directory, the one `pilotctl daemon start` +// uses (finishStaged). It gives each daemon a log of its own, +// pilot-.log, so the copy a daemon staged before it died is under a +// name no later daemon rotates. It considers only those names: any other +// .pilot.1 may be another program's file. Best effort: a copy it +// cannot finish stays for a later round. +func finishOrphans(path string) { + dir := filepath.Dir(path) + entries, err := os.ReadDir(dir) + if err != nil { + slog.Warn("log rotation: could not look for interrupted backups", "dir", dir, "err", err) + return + } + own := filepath.Base(stagingName(path)) + for _, e := range entries { + log, ok := strings.CutSuffix(e.Name(), stagingSuffix) + if !ok || !isDaemonStartLog(log) || e.Name() == own { + continue + } + if err := finishStaged(filepath.Join(dir, log), true); err != nil && !errors.Is(err, errBusy) { + slog.Warn("log rotation: could not finish interrupted backup", "path", filepath.Join(dir, e.Name()), "err", err) + } + } +} + +// isDaemonStartLog reports whether name is a log `pilotctl daemon start` +// names after its daemon: pilot-.log. Keep in step with +// cmd/pilotctl's daemon start. +func isDaemonStartLog(name string) bool { + pid, ok := strings.CutPrefix(name, "pilot-") + if !ok { + return false + } + pid, ok = strings.CutSuffix(pid, ".log") + if !ok || pid == "" { + return false + } + for _, c := range pid { + if c < '0' || c > '9' { + return false + } + } + return true +} + +// createStaged copies src (from its current offset to EOF) into a new +// file at dst and returns dst open and locked: the lock marks the copy as +// in use, so that no other daemon takes it for an interrupted one, until +// the caller has compressed it and closes the returned file. +// O_EXCL|O_NOFOLLOW: it never writes into an existing file or through a +// link, and removes only the file it created. +func createStaged(src *os.File, dst string) (*os.File, error) { + // #nosec G304 -- dst is derived from the daemon's own log path. + out, err := os.OpenFile(dst, os.O_WRONLY|os.O_CREATE|os.O_EXCL|oNoFollow, 0o600) + if err != nil { + return nil, err + } + held, err := holdStaged(dst, out) + if err != nil { + // Not removed: the name may no longer be this file, or another + // rotation is finishing it. + _ = out.Close() + return nil, err + } + _, err = io.Copy(out, src) + // Closing out reports a delayed write error (NFS) before the log is + // truncated; held keeps the lock. + if err = errors.Join(err, out.Close()); err != nil { + _ = os.Remove(dst) + _ = held.Close() + return nil, err + } + return held, nil +} + +// holdStaged opens the copy just created as out through a descriptor of +// its own, and locks that one, so out can be closed while the lock stays. +// The copy is still empty, and so passed over by finishOrphans; if +// another rotation of the same log took it anyway before the lock, it is +// left to that one. Where the filesystem has no flock, it carries on +// unlocked. +func holdStaged(dst string, out *os.File) (*os.File, error) { + // #nosec G304 -- dst is derived from the daemon's own log path. + held, err := os.OpenFile(dst, os.O_RDONLY|oNoFollow, 0) + if err != nil { + return nil, err + } + ofi, oerr := out.Stat() + hfi, herr := held.Stat() + if err = errors.Join(oerr, herr); err == nil && !os.SameFile(ofi, hfi) { + err = fmt.Errorf("%s was replaced while being created", dst) + } + if err == nil { + if lerr := tryLock(held); errors.Is(lerr, errBusy) { + err = fmt.Errorf("%s: %w", dst, lerr) + } else if !namesFile(dst, hfi) { + err = fmt.Errorf("%s was taken over by another rotation", dst) + } + } + if err != nil { + _ = held.Close() + return nil, err + } + return held, nil +} + +// compress gzips src into dst via a temp file, so a partial dst never +// appears, and removes src. src must be a regular file of ours; dst must +// be absent or a generation of ours, which it replaces. +func compress(src, dst string) error { + in, err := openOurs(src) + if err != nil { + return err + } + defer in.Close() + + tmp := dst + ".tmp" + // A temp file of ours is left from an interrupted compress; anything + // else at that name stops this one. + if exists, err := lookup(tmp); err != nil { + return err + } else if exists { + if err := os.Remove(tmp); err != nil && !errors.Is(err, fs.ErrNotExist) { + return err + } + } + // #nosec G304 -- tmp is derived from the daemon's own log path. + out, err := os.OpenFile(tmp, os.O_WRONLY|os.O_CREATE|os.O_EXCL|oNoFollow, 0o600) + if err != nil { + return err + } + zw := gzip.NewWriter(out) + _, copyErr := io.Copy(zw, in) + err = errors.Join(copyErr, zw.Close(), out.Close()) + if err == nil { + _, err = lookup(dst) + } + if err == nil { + err = os.Rename(tmp, dst) + } + if err != nil { + _ = os.Remove(tmp) + return err + } + return os.Remove(src) +} diff --git a/internal/logcap/logcap_darwin_test.go b/internal/logcap/logcap_darwin_test.go new file mode 100644 index 00000000..e63347df --- /dev/null +++ b/internal/logcap/logcap_darwin_test.go @@ -0,0 +1,65 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build darwin + +package logcap + +import ( + "errors" + "fmt" + "path/filepath" + "strings" + "testing" + + "golang.org/x/sys/unix" +) + +// TestCheckKeepsGenerationsOfAppendOnlyLog: an operator makes the log +// append-only for tamper resistance (chflags uappnd; chattr +a on +// Linux). The daemon's O_APPEND writes go on, but it can no longer +// truncate the log: its backups are kept rather than shifted out one per +// round, and no copy is left behind. +func TestCheckKeepsGenerationsOfAppendOnlyLog(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + for gen := 1; gen <= 3; gen++ { + writeFile(t, backupName(path, gen), fmt.Sprintf("generation %d", gen)) + } + f := openLog(t, path) + content := strings.Repeat("a", 50) + write(t, f, content) + if err := unix.Chflags(path, unix.UF_APPEND); err != nil { + t.Skipf("chflags uappnd: %v", err) + } + t.Cleanup(func() { _ = unix.Chflags(path, 0) }) + before := dirNames(t, dir) + + r := New(f, anywhere(10, 3)) + for round := range 3 { + rotated, err := r.Check() + if rotated || !errors.Is(err, errTruncate) || !errors.Is(err, unix.EPERM) { + t.Fatalf("round %d: Check = (%v, %v), want (false, errTruncate: EPERM)", round, rotated, err) + } + if got := dirNames(t, dir); !equal(got, before) { + t.Fatalf("round %d: dir = %v, want %v", round, got, before) + } + } + for gen := 1; gen <= 3; gen++ { + if got := readFile(t, backupName(path, gen)); got != fmt.Sprintf("generation %d", gen) { + t.Fatalf("%s = %q", backupName(path, gen), got) + } + } + + if err := unix.Chflags(path, 0); err != nil { + t.Fatal(err) + } + mustRotate(t, r) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf(".1.gz = %q, want the log", got) + } + for gen, want := range map[int]string{2: "generation 1", 3: "generation 2"} { + if got := readFile(t, backupName(path, gen)); got != want { + t.Fatalf("%s = %q, want %q", backupName(path, gen), got, want) + } + } +} diff --git a/internal/logcap/logcap_interrupted_test.go b/internal/logcap/logcap_interrupted_test.go new file mode 100644 index 00000000..74773d5e --- /dev/null +++ b/internal/logcap/logcap_interrupted_test.go @@ -0,0 +1,604 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import ( + "bufio" + "errors" + "os" + "os/exec" + "path/filepath" + "sort" + "strings" + "testing" + "time" +) + +// holdLock opens path and takes the lock a rotation in progress holds on +// its staged copy, from another open file description, as another daemon +// would. The lock is released when the test ends or on release(). +func holdLock(t *testing.T, path string) (release func()) { + t.Helper() + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + if err := tryLock(f); err != nil { + _ = f.Close() + t.Fatalf("lock %s: %v", path, err) + } + var once bool + release = func() { + if !once { + once = true + _ = f.Close() + } + } + t.Cleanup(release) + return release +} + +// pilotDir returns Options for a log directly in dir, as Pilot's own +// directory: the one `pilotctl daemon start` puts each daemon's log in, +// where a rotation also finishes the other daemons' interrupted ones. +func pilotDir(dir string, maxBytes int64, maxBackups int) Options { + return Options{MaxBytes: maxBytes, MaxBackups: maxBackups, Within: []string{dir}} +} + +// locked reports whether some open file description holds path's lock. +func locked(t *testing.T, path string) bool { + t.Helper() + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + defer f.Close() + err = tryLock(f) + if err != nil && !errors.Is(err, errBusy) { + t.Fatal(err) + } + return errors.Is(err, errBusy) +} + +// TestCheckFinishesAnotherLogsInterruptedRotation: `pilotctl daemon +// start` gives each daemon its own pilot-.log, so the copy a daemon +// staged before it was killed is under a name the next daemon never +// rotates. The next daemon's rotation finishes it into that log's +// generation 1 — and leaves the rest of the dead daemon's files as they +// were. +func TestCheckFinishesAnotherLogsInterruptedRotation(t *testing.T) { + dir := t.TempDir() + dead := filepath.Join(dir, "pilot-22.log") + deadLog := strings.Repeat("pilot-22 line\n", 5) + writeFile(t, dead, deadLog) + writeFile(t, stagingName(dead), "staged by pilot-22\n") + // Its shift had already moved generation 1 up before the copy. + writeFile(t, backupName(dead, 2), "pilot-22 generation 2") + + path := filepath.Join(dir, "pilot-40.log") + f := openLog(t, path) + content := strings.Repeat("pilot-40 line\n", 5) + write(t, f, content) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) + + if got := gunzip(t, backupName(dead, 1)); got != "staged by pilot-22\n" { + t.Fatalf("%s = %q, want the staged copy", backupName(dead, 1), got) + } + if exists(stagingName(dead)) { + t.Fatal("interrupted copy of another log left behind") + } + if got := readFile(t, backupName(dead, 2)); got != "pilot-22 generation 2" { + t.Fatalf("another log's generations were shifted: .2.gz = %q", got) + } + if got := readFile(t, dead); got != deadLog { + t.Fatalf("another log itself changed: %d bytes", len(got)) + } + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("own backup = %q, want the log", got) + } + want := []string{ + "pilot-22.log", + filepath.Base(backupName(dead, 1)), + filepath.Base(backupName(dead, 2)), + "pilot-40.log", + filepath.Base(backupName(path, 1)), + } + if got := dirNames(t, dir); !equal(got, want) { + t.Fatalf("dir = %v, want %v", got, want) + } +} + +// TestCheckLeavesAnotherRotationInProgressAlone: a staged copy another +// live daemon holds locked is still being written or compressed; it is +// not taken for an interrupted one until that lock goes away. +func TestCheckLeavesAnotherRotationInProgressAlone(t *testing.T) { + dir := t.TempDir() + other := filepath.Join(dir, "pilot-22.log") + writeFile(t, stagingName(other), "being copied\n") + release := holdLock(t, stagingName(other)) + + path := filepath.Join(dir, "pilot-40.log") + f := openLog(t, path) + r := New(f, pilotDir(dir, 10, 3)) + write(t, f, strings.Repeat("a", 50)) + mustRotate(t, r) + if got := readFile(t, stagingName(other)); got != "being copied\n" { + t.Fatalf("staged copy in progress changed: %q", got) + } + if exists(backupName(other, 1)) { + t.Fatal("staged copy in progress was compressed") + } + + release() + write(t, f, strings.Repeat("b", 50)) + mustRotate(t, r) + if got := gunzip(t, backupName(other, 1)); got != "being copied\n" { + t.Fatalf("%s = %q, want the copy once its rotation is gone", backupName(other, 1), got) + } +} + +// TestCheckLeavesEmptyStagedCopyOfAnotherLogAlone: an empty copy may be +// one another daemon has just created and not yet locked, so it is left +// alone; there is nothing in it to keep either way. +func TestCheckLeavesEmptyStagedCopyOfAnotherLogAlone(t *testing.T) { + dir := t.TempDir() + other := filepath.Join(dir, "pilot-22.log") + writeFile(t, stagingName(other), "") + + path := filepath.Join(dir, "pilot-40.log") + f := openLog(t, path) + write(t, f, strings.Repeat("c", 50)) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) + if !exists(stagingName(other)) { + t.Fatal("empty staged copy removed") + } + if exists(backupName(other, 1)) { + t.Fatal("empty staged copy compressed") + } +} + +// TestCheckOnlyFinishesStagedCopiesOfOurs: the search for other logs' +// interrupted rotations touches only regular files of this user at the +// staging names of `pilotctl daemon start`'s logs, pilot-.log.pilot.1; +// everything else in the directory — a link, a directory, another user's +// file at such a name, a bare ".pilot.1", other rotators' names, the +// staging name of any other log — is left as it was, and so is anything +// outside the directory. +func TestCheckOnlyFinishesStagedCopiesOfOurs(t *testing.T) { + parent := t.TempDir() + dir := filepath.Join(parent, "logs") + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + // What a bare ".pilot.1" would name, taken as the directory's own + // staged copy: in the parent, which rotation never vetted. + outside := stagingName(dir) + writeFile(t, outside, "outside the log directory\n") + secret := filepath.Join(t.TempDir(), "identity.json") + writeFile(t, secret, "SECRET-KEY-MATERIAL\n") + link := stagingName(filepath.Join(dir, "pilot-1.log")) + symlink(t, secret, link) + if err := os.Mkdir(stagingName(filepath.Join(dir, "pilot-2.log")), 0o700); err != nil { + t.Fatal(err) + } + theirs := stagingName(filepath.Join(dir, "pilot-3.log")) + writeFile(t, theirs, "another user's file\n") + fakeForeign(t, theirs) + untouched := map[string]string{ + theirs: "another user's file\n", + filepath.Join(dir, ".pilot.1"): "no log name\n", + filepath.Join(dir, "x.log.pilot.2"): "not a staging name\n", + filepath.Join(dir, "x.log.pilot.1.gz"): "not a staging name\n", + filepath.Join(dir, "x.log.1"): "logrotate's\n", + filepath.Join(dir, "x.log.pilot.1.bak"): "not a staging name\n", + } + // Staging names of logs that are not `pilotctl daemon start`'s. + for _, log := range []string{ + "x.log", "app", "pilot-daemon.log", "pilot-starting.log", + "pilot-.log", "pilot-12a.log", "pilot-12.log.1", "pilot-12", + } { + untouched[stagingName(filepath.Join(dir, log))] = "the staging name of " + log + "\n" + } + for name, content := range untouched { + writeFile(t, name, content) + } + // One that is: the scan did run. + orphan := filepath.Join(dir, "pilot-9.log") + writeFile(t, stagingName(orphan), "pilot-9's copy\n") + before := dirNames(t, dir) + + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + write(t, f, strings.Repeat("d", 50)) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) + + for name, want := range untouched { + if got := readFile(t, name); got != want { + t.Fatalf("%s = %q, want it untouched", name, got) + } + } + if !isSymlink(link) { + t.Fatal("planted link was removed or replaced") + } + if got := readFile(t, secret); got != "SECRET-KEY-MATERIAL\n" { + t.Fatalf("link target changed: %q", got) + } + if got := gunzip(t, backupName(orphan, 1)); got != "pilot-9's copy\n" { + t.Fatalf("%s = %q, want pilot-9's copy finished", backupName(orphan, 1), got) + } + var want []string + for _, name := range before { + if name != filepath.Base(stagingName(orphan)) { + want = append(want, name) + } + } + want = append(want, "daemon.log", filepath.Base(backupName(path, 1)), filepath.Base(backupName(orphan, 1))) + sort.Strings(want) + if got := dirNames(t, dir); !equal(got, want) { + t.Fatalf("dir = %v, want %v", got, want) + } + if got := readFile(t, outside); got != "outside the log directory\n" { + t.Fatalf("%s = %q, want it untouched", outside, got) + } + if got := dirNames(t, parent); !equal(got, []string{"logs", filepath.Base(outside)}) { + t.Fatalf("parent dir = %v, want nothing created or removed there", got) + } +} + +// TestCheckFinishesOrphansOnlyInPilotDirectory: other daemons' copies +// are finished only where `pilotctl daemon start` puts its logs, a +// Within directory itself. A log rotated anywhere else — explicitly, in a +// shared /var/log; as the brew service log, in brew's var/log; in a +// directory below ~/.pilot — leaves the other files in its directory +// alone, even at a pilot-.log.pilot.1 name. +func TestCheckFinishesOrphansOnlyInPilotDirectory(t *testing.T) { + for _, tc := range []struct { + name string + // opts for a log in dir, with pilot as ~/.pilot. + opts func(pilot, dir string) Options + dir func(root string) string + }{ + { + "explicit, outside Within", + func(pilot, _ string) Options { + return Options{MaxBytes: 10, MaxBackups: 3, Anywhere: true, Within: []string{pilot}} + }, + func(root string) string { return filepath.Join(root, "var", "log") }, + }, + { + "explicit, no Within", + func(string, string) Options { return anywhere(10, 3) }, + func(root string) string { return filepath.Join(root, "var", "log") }, + }, + { + "brew service log", + func(pilot, dir string) Options { + return Options{MaxBytes: 10, MaxBackups: 3, Within: []string{pilot}, Files: []string{filepath.Join(dir, "pilot-daemon.log")}} + }, + func(root string) string { return filepath.Join(root, "var", "log") }, + }, + { + "below Within", + func(pilot, _ string) Options { return Options{MaxBytes: 10, MaxBackups: 3, Within: []string{pilot}} }, + func(root string) string { return filepath.Join(root, ".pilot", "logs") }, + }, + } { + t.Run(tc.name, func(t *testing.T) { + root := t.TempDir() + pilot := filepath.Join(root, ".pilot") + dir := tc.dir(root) + for _, d := range []string{pilot, dir} { + if err := os.MkdirAll(d, 0o700); err != nil { + t.Fatal(err) + } + } + others := map[string]string{ + stagingName(filepath.Join(dir, "pilot-22.log")): "a pilot-.log copy\n", + filepath.Join(dir, "app.pilot.1"): "logrotate's delaycompress generation\n", + } + for name, content := range others { + writeFile(t, name, content) + } + path := filepath.Join(dir, "pilot-daemon.log") + f := openLog(t, path) + content := strings.Repeat("o", 50) + write(t, f, content) + mustRotate(t, New(f, tc.opts(pilot, dir))) + + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("own backup = %q, want the log", got) + } + for name, want := range others { + if got := readFile(t, name); got != want { + t.Fatalf("%s = %q, want it untouched", name, got) + } + } + want := []string{"app.pilot.1", "pilot-22.log.pilot.1", "pilot-daemon.log", filepath.Base(backupName(path, 1))} + sort.Strings(want) + if got := dirNames(t, dir); !equal(got, want) { + t.Fatalf("dir = %v, want %v", got, want) + } + }) + } +} + +// TestCheckOwnRotationInProgressStopsTheShift: when this log's own staged +// copy is held by a rotation in progress (another process writing the +// same log), this round keeps no backup and moves nothing, instead of +// shifting generations under that rotation; once the lock is gone the +// copy is finished as an interrupted one. +func TestCheckOwnRotationInProgressStopsTheShift(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + // The other rotation has shifted (.1.gz is free) and staged its copy. + writeFile(t, backupName(path, 2), "generation 2") + writeFile(t, stagingName(path), "the other rotation's copy\n") + release := holdLock(t, stagingName(path)) + + r := New(f, anywhere(10, 3)) + write(t, f, strings.Repeat("e", 50)) + rotated, err := r.Check() + if !rotated || !errors.Is(err, errBusy) { + t.Fatalf("Check = (%v, %v), want (true, errBusy)", rotated, err) + } + if got := readFile(t, path); got != "" { + t.Fatalf("log not truncated: %d bytes", len(got)) + } + want := []string{"daemon.log", filepath.Base(stagingName(path)), filepath.Base(backupName(path, 2))} + sort.Strings(want) + if got := dirNames(t, dir); !equal(got, want) { + t.Fatalf("dir = %v, want %v (nothing moved)", got, want) + } + + release() + write(t, f, strings.Repeat("g", 50)) + mustRotate(t, r) + for gen, want := range map[int]string{1: strings.Repeat("g", 50), 2: "the other rotation's copy\n"} { + if got := gunzip(t, backupName(path, gen)); got != want { + t.Fatalf("%s = %q, want %q", backupName(path, gen), got, want) + } + } + if got := readFile(t, backupName(path, 3)); got != "generation 2" { + t.Fatalf(".3.gz = %q, want the old generation 2", got) + } +} + +// TestCheckReleasesItsLockEachRound: a copy kept after a failed compress +// is not left locked, or the next round would take it for a rotation in +// progress and never finish it. +func TestCheckReleasesItsLockEachRound(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + tmp := backupName(path, 1) + ".tmp" + symlink(t, filepath.Join(t.TempDir(), "nowhere"), tmp) + + r := New(f, anywhere(10, 3)) + first := strings.Repeat("1", 50) + write(t, f, first) + rotateWithoutBackup(t, r, path) + if locked(t, stagingName(path)) { + t.Fatal("kept staged copy still locked after the round") + } + + if err := os.Remove(tmp); err != nil { + t.Fatal(err) + } + second := strings.Repeat("2", 50) + write(t, f, second) + mustRotate(t, r) + if got := gunzip(t, backupName(path, 2)); got != first { + t.Fatalf(".2.gz = %q, want the kept copy", got) + } + if got := gunzip(t, backupName(path, 1)); got != second { + t.Fatalf(".1.gz = %q, want the log", got) + } +} + +// TestCreateStagedHoldsTheLock: the copy is locked from creation until +// the rotation closes it, and its content is the log. +func TestCreateStagedHoldsTheLock(t *testing.T) { + dir := t.TempDir() + src := filepath.Join(dir, "daemon.log") + writeFile(t, src, "log content\n") + in, err := os.Open(src) + if err != nil { + t.Fatal(err) + } + defer in.Close() + + dst := stagingName(src) + held, err := createStaged(in, dst) + if err != nil { + t.Fatal(err) + } + if got := readFile(t, dst); got != "log content\n" { + t.Fatalf("staged copy = %q", got) + } + if !locked(t, dst) { + t.Fatal("staged copy not locked while held") + } + if err := held.Close(); err != nil { + t.Fatal(err) + } + if locked(t, dst) { + t.Fatal("staged copy still locked after close") + } +} + +// TestHoldStagedYieldsToAnotherRotation: if another rotation of the same +// log takes the new copy between its creation and its lock — locking it, +// or finishing and replacing it — this one gives the copy up rather than +// write into or remove a file that is no longer its own. +func TestHoldStagedYieldsToAnotherRotation(t *testing.T) { + create := func(t *testing.T) (string, *os.File) { + t.Helper() + dst := stagingName(filepath.Join(t.TempDir(), "daemon.log")) + out, err := os.OpenFile(dst, os.O_WRONLY|os.O_CREATE|os.O_EXCL, 0o600) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = out.Close() }) + return dst, out + } + + t.Run("locked by the other", func(t *testing.T) { + dst, out := create(t) + holdLock(t, dst) + if held, err := holdStaged(dst, out); err == nil { + held.Close() + t.Fatal("holdStaged took a copy another rotation holds") + } else if !errors.Is(err, errBusy) { + t.Fatalf("err = %v, want errBusy", err) + } + if !exists(dst) { + t.Fatal("copy removed") + } + }) + + t.Run("finished and replaced by the other", func(t *testing.T) { + dst, out := create(t) + if err := os.Remove(dst); err != nil { + t.Fatal(err) + } + writeFile(t, dst, "the other rotation's new copy\n") + if held, err := holdStaged(dst, out); err == nil { + held.Close() + t.Fatal("holdStaged took a copy that is no longer its own") + } + if got := readFile(t, dst); got != "the other rotation's new copy\n" { + t.Fatalf("other rotation's copy changed: %q", got) + } + }) +} + +// TestHelperStagedCopy is not a test: TestCheckFinishesCopyOfKilledDaemon +// runs the test binary as another daemon that stages a copy, holds it as +// a rotation does, and waits to be killed. +func TestHelperStagedCopy(t *testing.T) { + dst := os.Getenv("LOGCAP_HELPER_STAGED") + if dst == "" { + t.Skip("helper process for TestCheckFinishesCopyOfKilledDaemon") + } + in, err := os.Open(os.Getenv("LOGCAP_HELPER_LOG")) + if err != nil { + t.Fatal(err) + } + held, err := createStaged(in, dst) + if err != nil { + t.Fatal(err) + } + defer held.Close() + if _, err := os.Stdout.WriteString("staged\n"); err != nil { + t.Fatal(err) + } + time.Sleep(time.Minute) + t.Fatal("helper was not killed") +} + +// TestCheckFinishesCopyOfKilledDaemon: across processes, as in the field. +// A daemon killed (SIGKILL, OOM) mid-rotation leaves its copy; while it +// is alive another daemon leaves the copy alone, and once it is dead its +// lock is gone and the next rotation finishes the copy. +func TestCheckFinishesCopyOfKilledDaemon(t *testing.T) { + dir := t.TempDir() + dead := filepath.Join(dir, "pilot-22.log") + deadLog := strings.Repeat("pilot-22 line\n", 20) + writeFile(t, dead, deadLog) + + helper := exec.Command(os.Args[0], "-test.run=^TestHelperStagedCopy$", "-test.v") + helper.Env = append(os.Environ(), + "LOGCAP_HELPER_LOG="+dead, + "LOGCAP_HELPER_STAGED="+stagingName(dead)) + out, err := helper.StdoutPipe() + if err != nil { + t.Fatal(err) + } + helper.Stderr = os.Stderr + if err := helper.Start(); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + _ = helper.Process.Kill() + _ = helper.Wait() + }) + ready := make(chan bool, 1) + go func() { + sc := bufio.NewScanner(out) + for sc.Scan() { + if sc.Text() == "staged" { + ready <- true + break + } + } + close(ready) + // Drain -test.v output until the helper exits. + for sc.Scan() { + } + }() + select { + case ok := <-ready: + if !ok { + t.Fatal("helper exited before staging its copy") + } + case <-time.After(30 * time.Second): + t.Fatal("helper never staged its copy") + } + + path := filepath.Join(dir, "pilot-40.log") + f := openLog(t, path) + r := New(f, pilotDir(dir, 10, 3)) + write(t, f, strings.Repeat("h", 50)) + mustRotate(t, r) + if exists(backupName(dead, 1)) { + t.Fatal("copy of a live daemon's rotation was compressed") + } + + if err := helper.Process.Kill(); err != nil { + t.Fatal(err) + } + _ = helper.Wait() + + write(t, f, strings.Repeat("i", 50)) + mustRotate(t, r) + if got := gunzip(t, backupName(dead, 1)); got != deadLog { + t.Fatalf("%s = %d bytes, want the killed daemon's copy (%d)", backupName(dead, 1), len(got), len(deadLog)) + } + if exists(stagingName(dead)) { + t.Fatal("killed daemon's copy left behind") + } +} + +// TestCheckWithoutFileLocking: on a filesystem that cannot flock, a log +// is still rotated with backups and its own interrupted copy finished, +// as before locking existed; another log's copy, which might belong to a +// live rotation there is no telling apart, is left alone. +func TestCheckWithoutFileLocking(t *testing.T) { + orig := tryLock + tryLock = func(*os.File) error { return errors.New("operation not supported") } + t.Cleanup(func() { tryLock = orig }) + + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, stagingName(path), "own interrupted copy\n") + other := filepath.Join(dir, "pilot-22.log") + writeFile(t, stagingName(other), "another log's copy\n") + + content := strings.Repeat("k", 50) + write(t, f, content) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf(".1.gz = %q, want the log", got) + } + if got := gunzip(t, backupName(path, 2)); got != "own interrupted copy\n" { + t.Fatalf(".2.gz = %q, want the interrupted copy", got) + } + if got := readFile(t, stagingName(other)); got != "another log's copy\n" { + t.Fatalf("another log's copy changed: %q", got) + } + if exists(backupName(other, 1)) { + t.Fatal("another log's copy compressed without a lock to go by") + } +} diff --git a/internal/logcap/logcap_safety_test.go b/internal/logcap/logcap_safety_test.go new file mode 100644 index 00000000..c18089a4 --- /dev/null +++ b/internal/logcap/logcap_safety_test.go @@ -0,0 +1,729 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import ( + "context" + "errors" + "fmt" + "os" + "path/filepath" + "sort" + "strings" + "testing" + "time" +) + +// foreignUID is a uid that is neither this process's nor root's. +var foreignUID = os.Geteuid() + 4242 + +// fakeForeign makes files and directories with these base names look +// owned by another user; the tests cannot chown without root. +func fakeForeign(t *testing.T, names ...string) { + t.Helper() + foreign := map[string]bool{} + for _, n := range names { + foreign[filepath.Base(n)] = true + } + orig := ownerOf + ownerOf = func(fi os.FileInfo) (int, bool) { + if foreign[fi.Name()] { + return foreignUID, true + } + return orig(fi) + } + t.Cleanup(func() { ownerOf = orig }) +} + +func writeFile(t *testing.T, path, content string) { + t.Helper() + if err := os.WriteFile(path, []byte(content), 0o600); err != nil { + t.Fatal(err) + } +} + +func symlink(t *testing.T, target, link string) { + t.Helper() + if err := os.Symlink(target, link); err != nil { + t.Fatal(err) + } +} + +func isSymlink(path string) bool { + fi, err := os.Lstat(path) + return err == nil && fi.Mode()&os.ModeSymlink != 0 +} + +// dirNames lists dir's entries, sorted. +func dirNames(t *testing.T, dir string) []string { + t.Helper() + entries, err := os.ReadDir(dir) + if err != nil { + t.Fatal(err) + } + var names []string + for _, e := range entries { + names = append(names, e.Name()) + } + sort.Strings(names) + return names +} + +// rotateWithoutBackup runs one Check that must truncate the log but keep +// no backup, reporting why. +func rotateWithoutBackup(t *testing.T, r *Rotator, path string) { + t.Helper() + rotated, err := r.Check() + if !rotated { + t.Fatalf("Check did not truncate an over-limit log (err %v)", err) + } + if err == nil { + t.Fatal("Check kept no backup but reported no error") + } + if got := readFile(t, path); got != "" { + t.Fatalf("log not truncated: %d bytes", len(got)) + } +} + +// TestCheckLeavesOtherRotatorsFilesAlone: an operator whose own rotation +// (logrotate with compress + delaycompress, newsyslog, dateext) already +// manages the file keeps every generation it made, even ones owned by +// the daemon's user and sitting at the old .N.gz names. +func TestCheckLeavesOtherRotatorsFilesAlone(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "pilot-daemon.log") + f := openLog(t, path) + + foreign := map[string]string{ + path + ".1": "logrotate delaycompress generation\n", + path + ".0.gz": "newsyslog generation\n", + path + "-20260901.gz": "dateext generation\n", + path + ".1.gz.tmp": "someone's temp file\n", + } + for gen := 2; gen <= 7; gen++ { + foreign[fmt.Sprintf("%s.%d.gz", path, gen)] = fmt.Sprintf("logrotate generation %d\n", gen) + } + for name, content := range foreign { + writeFile(t, name, content) + } + + r := New(f, anywhere(10, 3)) + for i := range 5 { + write(t, f, fmt.Sprintf("round-%d %s\n", i, strings.Repeat("x", 20))) + mustRotate(t, r) + } + + for name, want := range foreign { + if got := readFile(t, name); got != want { + t.Fatalf("%s = %q, want it untouched (%q)", name, got, want) + } + } + for gen := 1; gen <= 3; gen++ { + want := fmt.Sprintf("round-%d ", 5-gen) + if got := gunzip(t, backupName(path, gen)); !strings.HasPrefix(got, want) { + t.Fatalf("%s = %q, want the round %d log", backupName(path, gen), got, 5-gen) + } + } + if exists(backupName(path, 4)) { + t.Fatal("kept more generations than maxBackups") + } +} + +// TestCheckNeverFollowsPlantedSymlinks: links at the names the old +// rotation wrote through (.1, .1.gz.tmp) and at logcap's own +// names are never followed — no file is created or overwritten at their +// targets — and the links themselves are left in place. +func TestCheckNeverFollowsPlantedSymlinks(t *testing.T) { + for _, tc := range []struct { + name string + link func(path string) string + wantBackup bool + }{ + {"legacy staging name", func(p string) string { return p + ".1" }, true}, + {"legacy temp name", func(p string) string { return p + ".1.gz.tmp" }, true}, + {"staging name", stagingName, false}, + {"temp name", func(p string) string { return backupName(p, 1) + ".tmp" }, false}, + {"generation name", func(p string) string { return backupName(p, 2) }, false}, + } { + t.Run(tc.name, func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + outside := t.TempDir() + dangling := filepath.Join(outside, "created-through-link") + victim := filepath.Join(outside, "victim") + writeFile(t, victim, "victim content\n") + + link := tc.link(path) + symlink(t, dangling, link) + // A second link to an existing file, where the name allows one. + var link2 string + if tc.name == "generation name" { + link2 = backupName(path, 1) + symlink(t, victim, link2) + } + + content := strings.Repeat("log line\n", 10) + write(t, f, content) + r := New(f, anywhere(10, 3)) + if tc.wantBackup { + mustRotate(t, r) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("backup = %q, want the log", got) + } + } else { + rotateWithoutBackup(t, r, path) + } + + if exists(dangling) { + t.Fatal("a file was created through the planted link") + } + if got := readFile(t, victim); got != "victim content\n" { + t.Fatalf("link target overwritten: %q", got) + } + for _, l := range []string{link, link2} { + if l != "" && !isSymlink(l) { + t.Fatalf("planted link %s was removed or replaced", l) + } + } + }) + } +} + +// TestCheckKeepsStagedCopyWhenTempNameIsTaken: when the temp name is +// occupied by something logcap must not touch, the log is still +// truncated and the staged copy is kept for a later round to finish, +// rather than lost. +func TestCheckKeepsStagedCopyWhenTempNameIsTaken(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + symlink(t, filepath.Join(t.TempDir(), "nowhere"), backupName(path, 1)+".tmp") + + content := strings.Repeat("kept\n", 10) + write(t, f, content) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, stagingName(path)); got != content { + t.Fatalf("staged copy = %q, want the log it copied", got) + } +} + +// TestCheckDoesNotConsumeLinkedSecret: a .pilot.1 linking to a file +// the daemon can read (identity.json) is not taken for an interrupted +// rotation's copy: the secret is not gzipped into the backup chain, and +// neither the file nor the link is touched. +func TestCheckDoesNotConsumeLinkedSecret(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + secret := filepath.Join(t.TempDir(), "identity.json") + writeFile(t, secret, "SECRET-KEY-MATERIAL\n") + symlink(t, secret, stagingName(path)) + + write(t, f, strings.Repeat("s", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + + if got := readFile(t, secret); got != "SECRET-KEY-MATERIAL\n" { + t.Fatalf("secret file changed: %q", got) + } + if !isSymlink(stagingName(path)) { + t.Fatal("planted link was removed or replaced") + } + gzs, _ := filepath.Glob(filepath.Join(dir, "*.gz")) + for _, gz := range gzs { + if strings.Contains(gunzip(t, gz), "SECRET") { + t.Fatalf("secret gzipped into %s", gz) + } + } +} + +// TestCheckLeavesOtherUsersFilesAlone: at logcap's own names, a file +// owned by another user is never read, renamed or removed. One in a slot +// the shift would move stops the backup before anything moved. +func TestCheckLeavesOtherUsersFilesAlone(t *testing.T) { + t.Run("in a kept slot", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, backupName(path, 1), "ours-1") + writeFile(t, backupName(path, 2), "theirs-2") + fakeForeign(t, backupName(path, 2)) + + write(t, f, strings.Repeat("a", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, backupName(path, 2)); got != "theirs-2" { + t.Fatalf("other user's file changed: %q", got) + } + if got := readFile(t, backupName(path, 1)); got != "ours-1" { + t.Fatalf("shift moved generations before stopping: .1 = %q", got) + } + if want := []string{"daemon.log", filepath.Base(backupName(path, 1)), filepath.Base(backupName(path, 2))}; !equal(dirNames(t, dir), want) { + t.Fatalf("dir = %v, want %v", dirNames(t, dir), want) + } + }) + + t.Run("in the slot the oldest is parked in", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + for gen := 1; gen <= 3; gen++ { + writeFile(t, backupName(path, gen), fmt.Sprintf("ours-%d", gen)) + } + writeFile(t, backupName(path, 4), "theirs-4") + fakeForeign(t, backupName(path, 4)) + before := dirNames(t, dir) + + write(t, f, strings.Repeat("p", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, backupName(path, 4)); got != "theirs-4" { + t.Fatalf("other user's file replaced: %q", got) + } + for gen := 1; gen <= 3; gen++ { + if got := readFile(t, backupName(path, gen)); got != fmt.Sprintf("ours-%d", gen) { + t.Fatalf("shift moved generations before stopping: %s = %q", backupName(path, gen), got) + } + } + if got := dirNames(t, dir); !equal(got, before) { + t.Fatalf("dir = %v, want %v", got, before) + } + }) + + t.Run("beyond the kept slots", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, backupName(path, 3), "ours-3") + writeFile(t, backupName(path, 4), "theirs-4") + writeFile(t, backupName(path, 5), "ours-5") + fakeForeign(t, backupName(path, 4)) + + write(t, f, strings.Repeat("b", 50)) + mustRotate(t, New(f, anywhere(10, 2))) + if exists(backupName(path, 3)) { + t.Fatal("stale generation beyond maxBackups not pruned") + } + if got := readFile(t, backupName(path, 4)); got != "theirs-4" { + t.Fatalf("other user's file changed: %q", got) + } + // Pruning stops at the first name that is not ours. + if !exists(backupName(path, 5)) { + t.Fatal("pruned past a file that is not ours") + } + }) + + t.Run("at the staging name", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, stagingName(path), "theirs-staged") + fakeForeign(t, stagingName(path)) + + write(t, f, strings.Repeat("c", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, stagingName(path)); got != "theirs-staged" { + t.Fatalf("other user's file changed: %q", got) + } + if exists(backupName(path, 1)) { + t.Fatal("other user's file consumed into a backup") + } + }) + + t.Run("where an interrupted rotation would finish", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, stagingName(path), "ours-staged") + writeFile(t, backupName(path, 1), "theirs-1") + fakeForeign(t, backupName(path, 1)) + + write(t, f, strings.Repeat("e", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, backupName(path, 1)); got != "theirs-1" { + t.Fatalf("other user's file replaced: %q", got) + } + if got := readFile(t, stagingName(path)); got != "ours-staged" { + t.Fatalf("staged copy lost: %q", got) + } + }) + + t.Run("at the temp name", func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + tmp := backupName(path, 1) + ".tmp" + writeFile(t, tmp, "theirs-tmp") + fakeForeign(t, tmp) + + write(t, f, strings.Repeat("d", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + if got := readFile(t, tmp); got != "theirs-tmp" { + t.Fatalf("other user's file changed: %q", got) + } + }) +} + +// TestCheckReplacesItsOwnStaleTemp: a temp file of ours left by an +// interrupted compress is replaced, not treated as foreign. +func TestCheckReplacesItsOwnStaleTemp(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, backupName(path, 1)+".tmp", "half-written gzip") + + content := strings.Repeat("e", 50) + write(t, f, content) + mustRotate(t, New(f, anywhere(10, 3))) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("backup = %q, want the log", got) + } + if exists(backupName(path, 1) + ".tmp") { + t.Fatal("temp file left behind") + } +} + +// sameDir reports whether a and b name the same directory (the log path +// resolved from a descriptor may differ, as /private/var for /var). +func sameDir(a, b string) bool { + afi, aerr := os.Stat(a) + bfi, berr := os.Stat(b) + return aerr == nil && berr == nil && os.SameFile(afi, bfi) +} + +// fakeGroup makes every directory's group look like the user's private +// group (private) or like a group other users are in. +func fakeGroup(t *testing.T, private bool) *[]string { + t.Helper() + var asked []string + orig := groupIsPrivate + groupIsPrivate = func(dir string, _ os.FileInfo) bool { + asked = append(asked, dir) + return private + } + t.Cleanup(func() { groupIsPrivate = orig }) + return &asked +} + +// TestCheckKeepsNoBackupInSharedDirectory: where other users can create +// names — writable by a group they are in or by others, sticky /tmp +// included — or in another user's directory, rotation only truncates and +// creates nothing. +func TestCheckKeepsNoBackupInSharedDirectory(t *testing.T) { + for _, tc := range []struct { + name string + mode os.FileMode + foreign bool + privateGroup bool + }{ + {"group-writable, shared group", 0o770, false, false}, + {"world-writable sticky", 0o777 | os.ModeSticky, false, true}, + {"world-writable, private group", 0o777, false, true}, + {"another user's", 0o755, true, false}, + {"another user's, private group", 0o775, true, true}, + } { + t.Run(tc.name, func(t *testing.T) { + dir := filepath.Join(t.TempDir(), "logs") + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + if err := os.Chmod(dir, tc.mode); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = os.Chmod(dir, 0o700) }) + if tc.foreign { + fakeForeign(t, dir) + } + fakeGroup(t, tc.privateGroup) + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, backupName(path, 1), "ours-1") + writeFile(t, stagingName(path), "ours-staged") + orphan := stagingName(filepath.Join(dir, "pilot-22.log")) + writeFile(t, orphan, "another log's staged copy") + + write(t, f, strings.Repeat("f", 50)) + // Within too, so the other log's copy is left alone because of + // the directory's permissions, not its scope. + opts := Options{MaxBytes: 10, MaxBackups: 3, Anywhere: true, Within: []string{dir}} + rotateWithoutBackup(t, New(f, opts), path) + want := []string{"daemon.log", filepath.Base(stagingName(path)), filepath.Base(backupName(path, 1)), filepath.Base(orphan)} + sort.Strings(want) + if got := dirNames(t, dir); !equal(got, want) { + t.Fatalf("dir = %v, want %v (nothing created, moved or removed)", got, want) + } + if got := readFile(t, backupName(path, 1)); got != "ours-1" { + t.Fatalf("generation changed: %q", got) + } + }) + } +} + +// TestCheckKeepsBackupsInPrivateGroupDirectory: a directory that is +// group-writable only because of the umask 002 of user-private-group +// systems — its group is the user's own — rotates as usual: generations +// are kept, shifted and finished, nothing is thrown away. +func TestCheckKeepsBackupsInPrivateGroupDirectory(t *testing.T) { + dir := filepath.Join(t.TempDir(), ".pilot") + if err := os.Mkdir(dir, 0o700); err != nil { + t.Fatal(err) + } + if err := os.Chmod(dir, 0o775); err != nil { + t.Fatal(err) + } + asked := fakeGroup(t, true) + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, stagingName(path), "interrupted round") + orphan := filepath.Join(dir, "pilot-22.log") + writeFile(t, stagingName(orphan), "another log's staged copy") + + r := New(f, Options{MaxBytes: 10, MaxBackups: 3, Within: []string{dir}}) + write(t, f, "round-0 "+strings.Repeat("x", 20)) + mustRotate(t, r) + if len(*asked) == 0 || !sameDir((*asked)[0], dir) { + t.Fatalf("group checked for %v, want %s", *asked, dir) + } + if got := gunzip(t, backupName(path, 2)); got != "interrupted round" { + t.Fatalf("%s = %q, want the interrupted round finished", backupName(path, 2), got) + } + if got := gunzip(t, backupName(orphan, 1)); got != "another log's staged copy" { + t.Fatalf("orphaned copy = %q, want it finished", got) + } + + for i := 1; i <= 2; i++ { + write(t, f, fmt.Sprintf("round-%d %s", i, strings.Repeat("x", 20))) + mustRotate(t, r) + } + for gen := 1; gen <= 3; gen++ { + want := fmt.Sprintf("round-%d ", 3-gen) + if got := gunzip(t, backupName(path, gen)); !strings.HasPrefix(got, want) { + t.Fatalf("%s = %q, want the round %d log", backupName(path, gen), got, 3-gen) + } + } + if readFile(t, path) != "" { + t.Fatal("log not truncated") + } +} + +// TestCheckRealOtherUserFiles repeats the ownership checks with real +// chown'd files and directories, which needs root (the linux container +// run). +func TestCheckRealOtherUserFiles(t *testing.T) { + if os.Geteuid() != 0 { + t.Skip("needs root to chown files to another user") + } + const other = 4242 + + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + names := map[string]string{ + stagingName(path): "theirs-staged", + backupName(path, 1) + ".tmp": "theirs-tmp", + backupName(path, 2): "theirs-2", + } + for name, content := range names { + writeFile(t, name, content) + if err := os.Chown(name, other, other); err != nil { + t.Fatal(err) + } + } + write(t, f, strings.Repeat("g", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + for name, want := range names { + if got := readFile(t, name); got != want { + t.Fatalf("%s = %q, want it untouched", name, got) + } + } + + // A directory owned by another (non-root) user: truncate only. + sub := filepath.Join(t.TempDir(), "theirs") + if err := os.Mkdir(sub, 0o755); err != nil { + t.Fatal(err) + } + if err := os.Chown(sub, other, other); err != nil { + t.Fatal(err) + } + subPath := filepath.Join(sub, "daemon.log") + g := openLog(t, subPath) + write(t, g, strings.Repeat("h", 50)) + rotateWithoutBackup(t, New(g, anywhere(10, 3)), subPath) + if got := dirNames(t, sub); !equal(got, []string{"daemon.log"}) { + t.Fatalf("dir = %v, want only the log", got) + } +} + +// TestWatchScopedToWithinDirs: without Anywhere, only a log inside one of +// the Within directories — at any depth, matched by identity so a +// symlinked path works — is watched. +func TestWatchScopedToWithinDirs(t *testing.T) { + root := t.TempDir() + pilot := filepath.Join(root, ".pilot") + logs := filepath.Join(pilot, "logs") + elsewhere := filepath.Join(root, "var-log") + for _, d := range []string{logs, elsewhere} { + if err := os.MkdirAll(d, 0o700); err != nil { + t.Fatal(err) + } + } + linkToPilot := filepath.Join(root, "pilot-link") + symlink(t, pilot, linkToPilot) + + inPilot := openLog(t, filepath.Join(pilot, "daemon.log")) + nested := openLog(t, filepath.Join(logs, "daemon.log")) + outside := openLog(t, filepath.Join(elsewhere, "daemon.log")) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + scoped := func(within ...string) Options { + return Options{MaxBytes: 1 << 30, MaxBackups: 1, Within: within} + } + for _, tc := range []struct { + name string + f *os.File + opts Options + want bool + }{ + {"inside", inPilot, scoped(pilot), true}, + {"nested inside", nested, scoped(pilot), true}, + {"inside, via a symlinked dir", inPilot, scoped(linkToPilot), true}, + {"outside", outside, scoped(pilot), false}, + {"no dirs", inPilot, scoped(), false}, + {"missing dir", inPilot, scoped(filepath.Join(root, "absent")), false}, + {"outside, explicit", outside, Options{MaxBytes: 1 << 30, MaxBackups: 1, Anywhere: true}, true}, + } { + if got := Watch(ctx, tc.f, tc.opts, time.Hour); got != tc.want { + t.Errorf("%s: Watch = %v, want %v", tc.name, got, tc.want) + } + } +} + +// TestWatchScopedToFiles: a log named in Files is watched, matched by +// name within the same directory (compared by identity), while the rest +// of that directory stays out of scope — the Homebrew service log, next +// to other formulae's logs in /var/log. +func TestWatchScopedToFiles(t *testing.T) { + root := t.TempDir() + varLog := filepath.Join(root, "brew", "var", "log") + sub := filepath.Join(varLog, "sub") + elsewhere := filepath.Join(root, "elsewhere") + for _, d := range []string{sub, elsewhere} { + if err := os.MkdirAll(d, 0o700); err != nil { + t.Fatal(err) + } + } + linkToVarLog := filepath.Join(root, "var-log-link") + symlink(t, varLog, linkToVarLog) + serviceLog := filepath.Join(varLog, "pilot-daemon.log") + + service := openLog(t, serviceLog) + neighbour := openLog(t, filepath.Join(varLog, "postgresql.log")) + sameNameElsewhere := openLog(t, filepath.Join(elsewhere, "pilot-daemon.log")) + sameNameBelow := openLog(t, filepath.Join(sub, "pilot-daemon.log")) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + scoped := func(files ...string) Options { + return Options{MaxBytes: 1 << 30, MaxBackups: 1, Files: files} + } + for _, tc := range []struct { + name string + f *os.File + opts Options + want bool + }{ + {"the file", service, scoped(serviceLog), true}, + {"the file, via a symlinked dir", service, scoped(filepath.Join(linkToVarLog, "pilot-daemon.log")), true}, + {"the file, next to Within", service, Options{MaxBytes: 1 << 30, MaxBackups: 1, Within: []string{elsewhere}, Files: []string{serviceLog}}, true}, + {"another file in its dir", neighbour, scoped(serviceLog), false}, + {"same name, another dir", sameNameElsewhere, scoped(serviceLog), false}, + {"same name, a subdirectory", sameNameBelow, scoped(serviceLog), false}, + {"missing dir", service, scoped(filepath.Join(root, "absent", "pilot-daemon.log")), false}, + } { + if got := Watch(ctx, tc.f, tc.opts, time.Hour); got != tc.want { + t.Errorf("%s: Watch = %v, want %v", tc.name, got, tc.want) + } + } +} + +// TestCheckStopsWhenFileLeavesScope: a Files log renamed — even within +// its directory, as newsyslog would — is no longer the daemon's to rotate. +func TestCheckStopsWhenFileLeavesScope(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "pilot-daemon.log") + f := openLog(t, path) + content := strings.Repeat("j", 50) + write(t, f, content) + r := New(f, Options{MaxBytes: 10, MaxBackups: 3, Files: []string{path}}) + + renamed := path + ".0" + if err := os.Rename(path, renamed); err != nil { + t.Fatal(err) + } + rotated, err := r.Check() + if rotated || !errors.Is(err, errOutOfScope) { + t.Fatalf("Check = (%v, %v), want (false, errOutOfScope)", rotated, err) + } + if got := readFile(t, renamed); got != content { + t.Fatalf("out-of-scope log changed: %d bytes", len(got)) + } + + if err := os.Rename(renamed, path); err != nil { + t.Fatal(err) + } + mustRotate(t, r) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("backup = %q, want the log", got) + } +} + +// TestCheckStopsWhenLogLeavesScope: a watched log moved out of the Within +// directories is no longer the daemon's to rotate: it is neither +// truncated nor backed up. +func TestCheckStopsWhenLogLeavesScope(t *testing.T) { + root := t.TempDir() + pilot := filepath.Join(root, ".pilot") + elsewhere := filepath.Join(root, "elsewhere") + for _, d := range []string{pilot, elsewhere} { + if err := os.Mkdir(d, 0o700); err != nil { + t.Fatal(err) + } + } + path := filepath.Join(pilot, "daemon.log") + f := openLog(t, path) + content := strings.Repeat("i", 50) + write(t, f, content) + r := New(f, Options{MaxBytes: 10, MaxBackups: 3, Within: []string{pilot}}) + + moved := filepath.Join(elsewhere, "daemon.log") + if err := os.Rename(path, moved); err != nil { + t.Fatal(err) + } + rotated, err := r.Check() + if rotated || !errors.Is(err, errOutOfScope) { + t.Fatalf("Check = (%v, %v), want (false, errOutOfScope)", rotated, err) + } + if got := readFile(t, moved); got != content { + t.Fatalf("out-of-scope log changed: %d bytes", len(got)) + } + if got := dirNames(t, elsewhere); !equal(got, []string{"daemon.log"}) { + t.Fatalf("files created next to the out-of-scope log: %v", got) + } + + // Moved back in, it rotates again. + if err := os.Rename(moved, path); err != nil { + t.Fatal(err) + } + mustRotate(t, r) +} + +func equal(a, b []string) bool { + if len(a) != len(b) { + return false + } + for i := range a { + if a[i] != b[i] { + return false + } + } + return true +} diff --git a/internal/logcap/logcap_test.go b/internal/logcap/logcap_test.go new file mode 100644 index 00000000..12e0643a --- /dev/null +++ b/internal/logcap/logcap_test.go @@ -0,0 +1,494 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import ( + "compress/gzip" + "context" + "errors" + "fmt" + "io" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +// openLog opens path the way launchd opens StandardErrorPath: write-only, +// append, create. +func openLog(t *testing.T, path string) *os.File { + t.Helper() + f, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0o644) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = f.Close() }) + return f +} + +func write(t *testing.T, f *os.File, s string) { + t.Helper() + if _, err := f.WriteString(s); err != nil { + t.Fatal(err) + } +} + +func readFile(t *testing.T, path string) string { + t.Helper() + b, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + return string(b) +} + +func gunzip(t *testing.T, path string) string { + t.Helper() + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + defer f.Close() + zr, err := gzip.NewReader(f) + if err != nil { + t.Fatalf("%s: %v", path, err) + } + b, err := io.ReadAll(zr) + if err != nil { + t.Fatalf("%s: %v", path, err) + } + return string(b) +} + +func exists(path string) bool { + _, err := os.Lstat(path) + return err == nil +} + +// anywhere returns Options that rotate the log wherever it lives, as an +// explicit -log-max-size does. +func anywhere(maxBytes int64, maxBackups int) Options { + return Options{MaxBytes: maxBytes, MaxBackups: maxBackups, Anywhere: true} +} + +func mustRotate(t *testing.T, r *Rotator) { + t.Helper() + rotated, err := r.Check() + if err != nil { + t.Fatalf("Check: %v", err) + } + if !rotated { + t.Fatal("Check did not rotate an over-limit log") + } +} + +func TestCheckBelowLimitIsNoop(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + write(t, f, strings.Repeat("x", 100)) + + r := New(f, anywhere(100, 3)) // exactly at the limit: not over it + rotated, err := r.Check() + if err != nil || rotated { + t.Fatalf("Check = (%v, %v), want (false, nil)", rotated, err) + } + if got := readFile(t, path); len(got) != 100 { + t.Fatalf("log size = %d, want 100 (untouched)", len(got)) + } + if exists(backupName(path, 1)) { + t.Fatal("backup written for a log under the limit") + } +} + +func TestCheckRotatesTruncatesAndGzips(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + first := strings.Repeat("first line\n", 20) + write(t, f, first) + + r := New(f, anywhere(100, 3)) + mustRotate(t, r) + + if got := readFile(t, path); got != "" { + t.Fatalf("log after rotation = %d bytes, want empty", len(got)) + } + if got := gunzip(t, backupName(path, 1)); got != first { + t.Fatalf("backup content mismatch: got %d bytes, want %d", len(got), len(first)) + } + if exists(stagingName(path)) { + t.Fatal("uncompressed staging copy left behind") + } + fi, err := os.Stat(backupName(path, 1)) + if err != nil { + t.Fatal(err) + } + if fi.Mode().Perm() != 0o600 { + t.Fatalf("backup mode = %v, want 0600", fi.Mode().Perm()) + } + + // The O_APPEND writer carries on at the new end of file: no sparse + // hole, no stale bytes. + write(t, f, "after\n") + if got := readFile(t, path); got != "after\n" { + t.Fatalf("log after post-rotation write = %q, want %q", got, "after\n") + } +} + +func TestCheckShiftsGenerationsAndDropsOldest(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + r := New(f, anywhere(10, 3)) + + contents := []string{"generation-A\n", "generation-B\n", "generation-C\n", "generation-D\n"} + for _, c := range contents { + write(t, f, c) + mustRotate(t, r) + } + + // Newest in .1, oldest kept in .3; generation-A fell off the end. + for gen, want := range map[int]string{1: contents[3], 2: contents[2], 3: contents[1]} { + if got := gunzip(t, backupName(path, gen)); got != want { + t.Fatalf("%s = %q, want %q", backupName(path, gen), got, want) + } + } + if exists(backupName(path, 4)) { + t.Fatal("kept more generations than maxBackups") + } +} + +func TestCheckRemovesGenerationsBeyondLoweredLimit(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + // Leftovers from a run with a larger -log-max-backups. + for gen := 1; gen <= 5; gen++ { + if err := os.WriteFile(backupName(path, gen), []byte("stale"), 0o600); err != nil { + t.Fatal(err) + } + } + write(t, f, strings.Repeat("y", 50)) + mustRotate(t, New(f, anywhere(10, 2))) + + if !exists(backupName(path, 1)) || !exists(backupName(path, 2)) { + t.Fatal("expected .1.gz and .2.gz") + } + for gen := 3; gen <= 5; gen++ { + if exists(backupName(path, gen)) { + t.Fatalf("%s survived with maxBackups=2", backupName(path, gen)) + } + } +} + +func TestCheckZeroBackupsJustTruncates(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + write(t, f, strings.Repeat("z", 50)) + + mustRotate(t, New(f, anywhere(10, 0))) + if got := readFile(t, path); got != "" { + t.Fatalf("log not truncated: %d bytes", len(got)) + } + matches, _ := filepath.Glob(path + ".*") + if len(matches) != 0 { + t.Fatalf("backups written with maxBackups=0: %v", matches) + } +} + +func TestCheckFinishesInterruptedRotation(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + // A previous rotation copied to .1 and died before compressing it; + // its shift had already moved the older backup to .2.gz. + if err := os.WriteFile(stagingName(path), []byte("interrupted\n"), 0o600); err != nil { + t.Fatal(err) + } + write(t, f, strings.Repeat("n", 50)) + mustRotate(t, New(f, anywhere(10, 3))) + + if got := gunzip(t, backupName(path, 2)); got != "interrupted\n" { + t.Fatalf(".2.gz = %q, want the interrupted generation", got) + } + if got := gunzip(t, backupName(path, 1)); got != strings.Repeat("n", 50) { + t.Fatalf(".1.gz = %q, want the current log", got) + } + if exists(stagingName(path)) { + t.Fatal("staging copy left behind") + } +} + +// readOnly opens path read-only. Such a descriptor cannot truncate the +// log, as the daemon's cannot when the log is append-only (chflags +// uappnd, chattr +a) or on a filesystem that refuses ftruncate. +func readOnly(t *testing.T, path string) *os.File { + t.Helper() + f, err := os.Open(path) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = f.Close() }) + return f +} + +// TestCheckKeepsGenerationsWhenLogCannotBeTruncated: a round that cannot +// truncate the log keeps no backup, so it moves nothing — every +// generation stays where it was, the oldest included, and no copy is +// left — however many rounds fail. Once the log can be truncated again, +// it rotates as if those rounds had not happened. +func TestCheckKeepsGenerationsWhenLogCannotBeTruncated(t *testing.T) { + for _, gens := range [][]int{{1, 2, 3}, {1, 3}, {2, 3}, {1}, {3}, nil} { + t.Run(fmt.Sprint(gens), func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + old := map[int]string{} + for _, gen := range gens { + old[gen] = fmt.Sprintf("generation %d", gen) + writeFile(t, backupName(path, gen), old[gen]) + } + content := strings.Repeat("l", 50) + writeFile(t, path, content) + before := dirNames(t, dir) + + r := New(readOnly(t, path), anywhere(10, 3)) + for round := range 3 { + rotated, err := r.Check() + if rotated || !errors.Is(err, errTruncate) { + t.Fatalf("round %d: Check = (%v, %v), want (false, errTruncate)", round, rotated, err) + } + if got := dirNames(t, dir); !equal(got, before) { + t.Fatalf("round %d: dir = %v, want %v (nothing moved, no copy left)", round, got, before) + } + for gen, want := range old { + if got := readFile(t, backupName(path, gen)); got != want { + t.Fatalf("round %d: %s = %q, want %q", round, backupName(path, gen), got, want) + } + } + if got := readFile(t, path); got != content { + t.Fatalf("round %d: log changed: %d bytes", round, len(got)) + } + } + + r.file = openLog(t, path) + mustRotate(t, r) + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf(".1.gz = %q, want the log", got) + } + for gen := 2; gen <= 3; gen++ { + want, ok := old[gen-1] + if got := exists(backupName(path, gen)); got != ok { + t.Fatalf("%s exists = %v, want %v", backupName(path, gen), got, ok) + } + if ok { + if got := readFile(t, backupName(path, gen)); got != want { + t.Fatalf("%s = %q, want %q", backupName(path, gen), got, want) + } + } + } + if exists(backupName(path, 4)) { + t.Fatal("kept more generations than maxBackups") + } + }) + } +} + +// TestUnstageLeavesGenerationOneFreeForACopyItCannotRemove: when the +// copy of a log that could not be truncated cannot be removed either, it +// is left for a later round to finish into generation 1, so the shift +// stays and only the parked generation is dropped, as before parking. +func TestUnstageLeavesGenerationOneFreeForACopyItCannotRemove(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + for gen := 1; gen <= 3; gen++ { + writeFile(t, backupName(path, gen), fmt.Sprintf("generation %d", gen)) + } + parked, err := shiftBackups(path, 3) + if err != nil || !parked { + t.Fatalf("shiftBackups = (%v, %v), want (true, nil)", parked, err) + } + // A name os.Remove fails on: a directory that is not empty. + if err := os.Mkdir(stagingName(path), 0o700); err != nil { + t.Fatal(err) + } + writeFile(t, filepath.Join(stagingName(path), "x"), "x") + + if err := unstage(path, 3, parked); err == nil { + t.Fatal("unstage reported no error for a copy it could not remove") + } + if exists(backupName(path, 1)) { + t.Fatal("generation 1 taken back while a copy is waiting for it") + } + for gen, want := range map[int]string{2: "generation 1", 3: "generation 2"} { + if got := readFile(t, backupName(path, gen)); got != want { + t.Fatalf("%s = %q, want %q", backupName(path, gen), got, want) + } + } + if exists(backupName(path, 4)) { + t.Fatal("parked generation not dropped") + } +} + +// TestRetryAfter: after each round in a row that could not truncate the +// log, the wait doubles, up to 64 intervals. +func TestRetryAfter(t *testing.T) { + for failures, want := range map[int]time.Duration{ + 1: 1, 2: 2, 3: 4, 4: 8, 5: 16, 6: 32, 7: 64, 8: 64, 1000: 64, + } { + if got := retryAfter(time.Minute, failures); got != want*time.Minute { + t.Errorf("retryAfter(1m, %d) = %v, want %v", failures, got, want*time.Minute) + } + } +} + +// TestTickBacksOffWhileLogCannotBeTruncated: the watcher does not copy a +// log it cannot truncate every interval: it waits longer after each +// failed round, and goes back to the interval once a round gets through. +func TestTickBacksOffWhileLogCannotBeTruncated(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + writeFile(t, path, strings.Repeat("t", 50)) + r := New(readOnly(t, path), anywhere(10, 3)) + + for i, want := range []time.Duration{1, 2, 4, 8, 16, 32, 64, 64} { + wait, ok := r.tick(time.Minute) + if !ok || wait != want*time.Minute { + t.Fatalf("failed round %d: tick = (%v, %v), want (%v, true)", i+1, wait, ok, want*time.Minute) + } + } + + w := openLog(t, path) + r.file = w + if wait, ok := r.tick(time.Minute); !ok || wait != time.Minute { + t.Fatalf("rotating round: tick = (%v, %v), want (1m, true)", wait, ok) + } + if got := readFile(t, path); got != "" { + t.Fatalf("log not truncated: %d bytes", len(got)) + } + + write(t, w, strings.Repeat("u", 50)) + r.file = readOnly(t, path) + if wait, ok := r.tick(time.Minute); !ok || wait != time.Minute { + t.Fatalf("first failed round after one got through: tick = (%v, %v), want (1m, true)", wait, ok) + } +} + +// TestCheckNonAppendWriterRewinds: a writer that did not open the file +// O_APPEND (a shell's `2>file`) shares the descriptor offset; rotation +// must rewind it or the next write re-creates the old size as a hole. +func TestCheckNonAppendWriterRewinds(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o644) + if err != nil { + t.Fatal(err) + } + defer f.Close() + write(t, f, strings.Repeat("w", 50)) + + mustRotate(t, New(f, anywhere(10, 1))) + write(t, f, "next\n") + if got := readFile(t, path); got != "next\n" { + t.Fatalf("log = %q (%d bytes), want %q — offset not rewound", got, len(got), "next\n") + } +} + +// TestCheckTruncatesWithoutBackupWhenPathIsGone: an unlinked log still +// fills the disk through the open descriptor, so it is truncated even +// though no backup can be made. +func TestCheckTruncatesWithoutBackupWhenPathIsGone(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + write(t, f, strings.Repeat("d", 50)) + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + + rotated, err := New(f, anywhere(10, 3)).Check() + if !rotated { + t.Fatalf("Check did not truncate an unlinked over-limit log (err %v)", err) + } + if err == nil { + t.Fatal("expected an error reporting the missing backup") + } + fi, err := f.Stat() + if err != nil { + t.Fatal(err) + } + if fi.Size() != 0 { + t.Fatalf("unlinked log size = %d, want 0", fi.Size()) + } + if matches, _ := filepath.Glob(filepath.Join(dir, "*.gz")); len(matches) != 0 { + t.Fatalf("backup written for an unlinked log: %v", matches) + } +} + +// TestCheckFollowsRenamedLog: fdPath resolves the file's current name, +// so backups land next to wherever the open log now lives. +func TestCheckFollowsRenamedLog(t *testing.T) { + dir := t.TempDir() + orig := filepath.Join(dir, "daemon.log") + f := openLog(t, orig) + write(t, f, strings.Repeat("r", 50)) + moved := filepath.Join(dir, "moved.log") + if err := os.Rename(orig, moved); err != nil { + t.Fatal(err) + } + + mustRotate(t, New(f, anywhere(10, 1))) + if !exists(backupName(moved, 1)) { + t.Fatal("backup not written next to the renamed log") + } +} + +func TestWatchNoopForNonRegularFiles(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + pr, pw, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + defer pr.Close() + defer pw.Close() + if Watch(ctx, pw, anywhere(1, 3), time.Minute) { + t.Fatal("Watch started on a pipe (journald/systemd case)") + } + + devnull, err := os.OpenFile(os.DevNull, os.O_WRONLY, 0) + if err != nil { + t.Fatal(err) + } + defer devnull.Close() + if Watch(ctx, devnull, anywhere(1, 3), time.Minute) { + t.Fatal("Watch started on a character device (terminal case)") + } +} + +func TestWatchDisabledByZeroLimit(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + if Watch(context.Background(), f, anywhere(0, 3), time.Minute) { + t.Fatal("Watch started with maxBytes=0 (disabled)") + } +} + +func TestWatchRotatesInBackground(t *testing.T) { + path := filepath.Join(t.TempDir(), "daemon.log") + f := openLog(t, path) + content := strings.Repeat("background\n", 10) + write(t, f, content) + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + if !Watch(ctx, f, anywhere(20, 1), 10*time.Millisecond) { + t.Fatal("Watch did not start on a regular file") + } + deadline := time.Now().Add(5 * time.Second) + for !exists(backupName(path, 1)) { + if time.Now().After(deadline) { + t.Fatal("background watcher never rotated the log") + } + time.Sleep(10 * time.Millisecond) + } + cancel() + if got := gunzip(t, backupName(path, 1)); got != content { + t.Fatalf("backup = %d bytes, want %d", len(got), len(content)) + } +} diff --git a/internal/logcap/main_unix_test.go b/internal/logcap/main_unix_test.go new file mode 100644 index 00000000..3a11ea39 --- /dev/null +++ b/internal/logcap/main_unix_test.go @@ -0,0 +1,21 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build darwin || linux + +package logcap + +import ( + "os" + "syscall" + "testing" +) + +// TestMain runs the tests under umask 022, whatever the caller's. Under +// umask 002 t.TempDir's directories are group-writable, and on macOS their +// group is staff, which every local account is in, so rotation there +// (rightly) keeps no backup. The tests about directory permissions set +// them explicitly. +func TestMain(m *testing.M) { + syscall.Umask(0o022) + os.Exit(m.Run()) +} diff --git a/internal/logcap/owner_other.go b/internal/logcap/owner_other.go new file mode 100644 index 00000000..485b3598 --- /dev/null +++ b/internal/logcap/owner_other.go @@ -0,0 +1,14 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build !darwin && !linux + +package logcap + +import "os" + +// Rotation never runs here (fdPathSupported is false); these only keep +// the package building. + +const oNoFollow = 0 + +func fileOwner(os.FileInfo) (int, bool) { return 0, false } diff --git a/internal/logcap/owner_unix.go b/internal/logcap/owner_unix.go new file mode 100644 index 00000000..fd80f960 --- /dev/null +++ b/internal/logcap/owner_unix.go @@ -0,0 +1,23 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +//go:build darwin || linux + +package logcap + +import ( + "os" + "syscall" +) + +// oNoFollow makes opening a symlink fail (ELOOP) instead of opening its +// target. +const oNoFollow = syscall.O_NOFOLLOW + +// fileOwner returns the uid that owns fi. +func fileOwner(fi os.FileInfo) (int, bool) { + st, ok := fi.Sys().(*syscall.Stat_t) + if !ok { + return 0, false + } + return int(st.Uid), true +} diff --git a/layers.yaml b/layers.yaml index 315ca631..9ca5a13c 100644 --- a/layers.yaml +++ b/layers.yaml @@ -111,6 +111,7 @@ utilities: - github.com/pilot-protocol/pilotprotocol/internal/validate - github.com/pilot-protocol/pilotprotocol/internal/nodesapi - github.com/pilot-protocol/pilotprotocol/internal/motd + - github.com/pilot-protocol/pilotprotocol/internal/logcap - github.com/pilot-protocol/pilotprotocol/pkg/secure - github.com/pilot-protocol/pilotprotocol/pkg/config - github.com/pilot-protocol/pilotprotocol/pkg/logging diff --git a/pkg/daemon/exit.go b/pkg/daemon/exit.go new file mode 100644 index 00000000..6ac6c5de --- /dev/null +++ b/pkg/daemon/exit.go @@ -0,0 +1,110 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package daemon + +import ( + "log/slog" + "os" + "sync" + "sync/atomic" + "time" +) + +// Supervisor-respawn exits. +// +// Some failure modes are only cured by a fresh process — the rx watchdog's +// hard escalation (rxwatchdog.go) exits non-zero so launchd (KeepAlive +// SuccessfulExit=false) / systemd (Restart=always) respawn the daemon. +// +// That exit used to be a direct os.Exit, which skipped the composition +// root's graceful shutdown (cmd/daemon: Daemon.Stop + runtime.StopPlugins). +// StopPlugins is what stops the app-store supervisor and terminates its +// child app processes; apps run in their own process group, so every +// watchdog exit orphaned all of them. One laptop accumulated 94 copies of +// each of 12 apps (~2.8 GB RSS) in a week. +// +// requestSupervisorExit now hands the exit to the host process instead: +// the handler installed with SetExitHandler (cmd/daemon's shutdown loop) +// runs the normal teardown and then exits with the requested code, so the +// supervisor still sees a non-zero status and respawns. The teardown can +// itself hang when the transport is wedged, so a hard deadline is armed +// before the handler runs: when it expires the process exits with the same +// code regardless. With no handler installed (embedders, bare test +// daemons) the request exits immediately — the pre-existing behavior. + +// supervisorExitDeadline bounds the graceful path of a supervisor-respawn +// exit. Long enough for Daemon.Stop (its own 5s background-goroutine +// wait) plus StopPlugins (5s); short enough that a wedged teardown still +// respawns promptly. +const supervisorExitDeadline = 15 * time.Second + +// ExitRequest is a deliberate self-exit the daemon asks its host process +// to perform after a graceful shutdown. +type ExitRequest struct { + // Code is the process exit status. Non-zero so the supervisor + // respawns (rxWedgeExitCode for the rx watchdog). + Code int + // Reason is a short machine-readable cause for logs, e.g. "rx-wedge". + Reason string +} + +var ( + exitHandler atomic.Pointer[func(ExitRequest)] + exitRequested atomic.Bool + + // exitSeamMu guards the test seams below. Production never writes + // them; tests swap them (see zz_exit_request_test.go). + exitSeamMu sync.Mutex + // hardExit terminates the process. + hardExit = os.Exit + // exitDeadline is supervisorExitDeadline outside tests. + exitDeadline = supervisorExitDeadline +) + +// SetExitHandler installs fn as the receiver of supervisor-respawn exit +// requests. fn must not block: it should hand the request to the +// goroutine that owns shutdown (cmd/daemon forwards it into its shutdown +// loop) and return. That goroutine runs the graceful teardown and exits +// the process with req.Code. nil uninstalls the handler, restoring the +// immediate os.Exit. +func SetExitHandler(fn func(ExitRequest)) { + if fn == nil { + exitHandler.Store(nil) + return + } + exitHandler.Store(&fn) +} + +// requestSupervisorExit asks the host process to shut down gracefully and +// exit with req.Code, forcing the exit after exitDeadline. Only the first +// request per process takes effect: later ones (another subsystem, or a +// tick racing the teardown) are dropped so the code and the deadline stay +// those of the first. +func requestSupervisorExit(req ExitRequest) { + if !exitRequested.CompareAndSwap(false, true) { + return + } + exitSeamMu.Lock() + exit, deadline := hardExit, exitDeadline + exitSeamMu.Unlock() + + h := exitHandler.Load() + if h == nil { + exit(req.Code) + return + } + // Arm the deadline BEFORE handing off: if the handler or the teardown + // it triggers wedges, the process still exits for respawn. + time.AfterFunc(deadline, func() { + slog.Error("graceful shutdown did not finish before the exit deadline — forcing exit", + "reason", req.Reason, + "exit_code", req.Code, + "deadline", deadline.String()) + exit(req.Code) + }) + slog.Info("requesting graceful shutdown for supervisor respawn", + "reason", req.Reason, + "exit_code", req.Code, + "deadline", deadline.String()) + (*h)(req) +} diff --git a/pkg/daemon/rxwatchdog.go b/pkg/daemon/rxwatchdog.go index 2880f012..2f9a6d8d 100644 --- a/pkg/daemon/rxwatchdog.go +++ b/pkg/daemon/rxwatchdog.go @@ -35,10 +35,12 @@ import ( // MsgDiscover reply doubles as an active inbound probe — plus // reRegister with the registry. Heals transient beacon endpoint // staleness without touching the transport. -// 2. Hard: exit with rxWedgeExitCode. launchd (KeepAlive -// SuccessfulExit=false) and systemd (Restart=always) respawn the -// daemon with a fresh socket + registration — the remedy that is -// known to clear the wedge. Guarded so it cannot flap: +// 2. Hard: exit with rxWedgeExitCode, after a graceful shutdown that +// stops the plugins (and so the app-store's child apps) — see +// exit.go. launchd (KeepAlive SuccessfulExit=false) and systemd +// (Restart=always) respawn the daemon with a fresh socket + +// registration — the remedy that is known to clear the wedge. +// Guarded so it cannot flap: // only after PktsRecv has progressed at least once this process // (a never-worked config soft-recovers forever instead of // boot-looping), only when the registry was reachable within @@ -113,8 +115,12 @@ const ( ) // rxWatchdogExit is swapped by tests to observe the hard escalation -// without killing the test process. -var rxWatchdogExit = func(code int) { os.Exit(code) } +// without killing the test process. It requests a graceful shutdown +// followed by exit(code) rather than calling os.Exit directly, so the +// app-store plugin still reaps its child apps (see exit.go). +var rxWatchdogExit = func(code int) { + requestSupervisorExit(ExitRequest{Code: code, Reason: "rx-wedge"}) +} // rxWatchdogState carries the loop's tick-to-tick memory. Kept as a // struct (not loop locals) so tests can drive rxWatchdogTick directly, @@ -178,7 +184,12 @@ func (d *Daemon) rxWatchdogLoop() { d.rxWatchdogResume(st, now, gap) } lastTick = now - d.rxWatchdogTick(st, now) + if d.rxWatchdogTick(st, now) == rxActionExit { + // Exit requested; shutdown is in flight. Stop ticking so + // a slow teardown can't re-escalate and record a second + // exit against the restart-loop breaker. + return + } } } } diff --git a/pkg/daemon/zz_exit_request_test.go b/pkg/daemon/zz_exit_request_test.go new file mode 100644 index 00000000..e2479352 --- /dev/null +++ b/pkg/daemon/zz_exit_request_test.go @@ -0,0 +1,167 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package daemon + +import ( + "path/filepath" + "testing" + "time" +) + +// swapExitSeamsForTest stubs the process-exit seams behind +// requestSupervisorExit and resets the once-per-process latch. The +// returned channel receives every code passed to hardExit. Like +// swapExitForTest, callers must NOT use t.Parallel(): the seams and the +// installed handler are package-global. +func swapExitSeamsForTest(t *testing.T, deadline time.Duration) <-chan int { + t.Helper() + exited := make(chan int, 4) + exitSeamMu.Lock() + prevExit, prevDeadline := hardExit, exitDeadline + hardExit = func(code int) { + select { + case exited <- code: + default: + } + } + exitDeadline = deadline + exitSeamMu.Unlock() + prevHandler := exitHandler.Load() + exitRequested.Store(false) + t.Cleanup(func() { + exitSeamMu.Lock() + hardExit, exitDeadline = prevExit, prevDeadline + exitSeamMu.Unlock() + exitHandler.Store(prevHandler) + exitRequested.Store(false) + }) + return exited +} + +// captureExitRequests installs a handler that records requests, standing +// in for cmd/daemon's shutdown loop. +func captureExitRequests(t *testing.T) <-chan ExitRequest { + t.Helper() + got := make(chan ExitRequest, 4) + SetExitHandler(func(req ExitRequest) { got <- req }) + return got +} + +// TestRequestSupervisorExitHandsOffToHandler: with a handler installed the +// request goes to the host's graceful shutdown path — the process is NOT +// exited on the spot (that was what orphaned the app-store's children). +func TestRequestSupervisorExitHandsOffToHandler(t *testing.T) { + exited := swapExitSeamsForTest(t, time.Hour) + got := captureExitRequests(t) + + requestSupervisorExit(ExitRequest{Code: rxWedgeExitCode, Reason: "rx-wedge"}) + + select { + case req := <-got: + if req.Code != rxWedgeExitCode || req.Reason != "rx-wedge" { + t.Fatalf("handler got %+v, want code %d reason rx-wedge", req, rxWedgeExitCode) + } + case <-time.After(2 * time.Second): + t.Fatal("exit request never reached the handler") + } + select { + case code := <-exited: + t.Fatalf("process exited immediately (code %d) instead of via graceful shutdown", code) + default: + } +} + +// TestRequestSupervisorExitDeadlineForcesExit: if the graceful shutdown +// hangs (wedged transport), the armed deadline exits anyway with the +// requested code so the supervisor still respawns. +func TestRequestSupervisorExitDeadlineForcesExit(t *testing.T) { + exited := swapExitSeamsForTest(t, 20*time.Millisecond) + // A handler that accepts the request and then never exits — the + // teardown it would have triggered is stuck. + SetExitHandler(func(ExitRequest) {}) + + requestSupervisorExit(ExitRequest{Code: rxWedgeExitCode, Reason: "rx-wedge"}) + + select { + case code := <-exited: + if code != rxWedgeExitCode { + t.Fatalf("forced exit code = %d, want %d", code, rxWedgeExitCode) + } + case <-time.After(5 * time.Second): + t.Fatal("deadline never forced the exit") + } +} + +// TestRequestSupervisorExitWithoutHandlerExitsImmediately: embedders that +// never install a handler keep the old direct-exit behavior. +func TestRequestSupervisorExitWithoutHandlerExitsImmediately(t *testing.T) { + exited := swapExitSeamsForTest(t, time.Hour) + SetExitHandler(nil) + + requestSupervisorExit(ExitRequest{Code: rxWedgeExitCode, Reason: "rx-wedge"}) + + select { + case code := <-exited: + if code != rxWedgeExitCode { + t.Fatalf("exit code = %d, want %d", code, rxWedgeExitCode) + } + default: + t.Fatal("no handler installed but the process was not exited") + } +} + +// TestRequestSupervisorExitFirstRequestWins: a second request (another +// subsystem, or a tick racing the teardown) must not re-arm the deadline +// or change the exit code. +func TestRequestSupervisorExitFirstRequestWins(t *testing.T) { + swapExitSeamsForTest(t, time.Hour) + got := captureExitRequests(t) + + requestSupervisorExit(ExitRequest{Code: rxWedgeExitCode, Reason: "first"}) + requestSupervisorExit(ExitRequest{Code: 1, Reason: "second"}) + + if req := <-got; req.Reason != "first" { + t.Fatalf("first request = %+v, want reason first", req) + } + select { + case req := <-got: + t.Fatalf("second request reached the handler: %+v", req) + default: + } +} + +// TestRxWatchdogHardExitRequestsGracefulShutdown drives the real +// (unswapped) rxWatchdogExit: the hard escalation records the exit for the +// restart-loop breaker, then hands exit code 86 to the host's shutdown +// path instead of calling os.Exit. +func TestRxWatchdogHardExitRequestsGracefulShutdown(t *testing.T) { + exited := swapExitSeamsForTest(t, time.Hour) + got := captureExitRequests(t) + + d := newRxWatchdogTestDaemon(t) + now := time.Now() + d.config.IdentityPath = filepath.Join(t.TempDir(), "id") + d.lastRegistryOKNano.Store(now.UnixNano()) + + st := wedgeState(d, now) + if action := d.rxWatchdogTick(st, now); action != rxActionExit { + t.Fatalf("action = %q, want %q", action, rxActionExit) + } + select { + case req := <-got: + if req.Code != rxWedgeExitCode { + t.Fatalf("requested exit code = %d, want %d", req.Code, rxWedgeExitCode) + } + default: + t.Fatal("hard escalation did not request a graceful shutdown") + } + select { + case code := <-exited: + t.Fatalf("watchdog exited directly (code %d), skipping plugin shutdown", code) + default: + } + path := rxWedgeExitLogPath(d.config.IdentityPath) + if n := len(recentRxWedgeExits(path, now, rxWedgeLoopWindow)); n != 1 { + t.Fatalf("recorded exits = %d, want 1 (recorded before the request)", n) + } +}