From d3a9370aa49ecf0b76aa94c859e19c371a7e50f9 Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Wed, 23 Sep 2026 23:59:06 +0300 Subject: [PATCH 1/6] fix(daemon): route watchdog exit through graceful shutdown The rx watchdog's hard escalation called os.Exit(86) directly, skipping cmd/daemon's Daemon.Stop + runtime.StopPlugins. StopPlugins is what stops the app-store supervisor and terminates its child apps; they run in their own process group, so every watchdog respawn orphaned all of them (94 copies of each of 12 apps, ~2.8 GB RSS, on one laptop in a week). - pkg/daemon/exit.go: requestSupervisorExit hands the exit to a host handler (SetExitHandler) and arms a 15s hard deadline that os.Exits with the same code if the teardown hangs. No handler installed -> immediate exit, the previous behavior for embedders. - rxWatchdogExit (the test seam) now requests the graceful exit; the watchdog loop stops ticking once it has, so a slow teardown can't record a second exit against the restart-loop breaker. - cmd/daemon: the shutdown loop receives exit requests alongside signals and fleet lifecycle requests, runs the normal teardown, then exits with the requested code so launchd/systemd still respawn. Daemon.Stop gets an 8s budget after which plugins are stopped anyway (a wedged transport can hang it). Startup failures after StartPlugins now stop plugins before exiting instead of log.Fatalf. pathwatch.go only borrows the seam pattern; it never exits. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 11 ++ cmd/daemon/main.go | 58 ++++------ cmd/daemon/shutdown.go | 135 +++++++++++++++++++++++ cmd/daemon/shutdown_test.go | 161 +++++++++++++++++++++++++++ pkg/daemon/exit.go | 110 +++++++++++++++++++ pkg/daemon/rxwatchdog.go | 25 +++-- pkg/daemon/zz_exit_request_test.go | 167 +++++++++++++++++++++++++++++ 7 files changed, 623 insertions(+), 44 deletions(-) create mode 100644 cmd/daemon/shutdown.go create mode 100644 cmd/daemon/shutdown_test.go create mode 100644 pkg/daemon/exit.go create mode 100644 pkg/daemon/zz_exit_request_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 83b6b90b..df69010b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,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/main.go b/cmd/daemon/main.go index efff87a9..0c49688a 100644 --- a/cmd/daemon/main.go +++ b/cmd/daemon/main.go @@ -501,7 +501,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 +513,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 +618,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/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) + } +} From cecd4e00fe982b4b2b73b1ce86ce7aeb0a1ea839 Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Thu, 24 Sep 2026 00:00:59 +0300 Subject: [PATCH 2/6] feat(daemon): cap the daemon's own log file (copy-truncate rotation) launchd never rotates StandardOutPath/StandardErrorPath, so ~/.pilot/daemon.log grew without bound (22 MB on one laptop; a June log was 13 MB gzipped). internal/logcap watches stderr when it is a regular file: every minute it fstats the descriptor and, past the limit, copies the file to .1, truncates the original through the daemon's own descriptor (rewinding first, for non-O_APPEND writers), then gzips the copy into .1.gz, shifting older generations up to .N.gz. launchd and pilotctl open the log O_APPEND and children share the file description, so truncation is safe for every writer. The path is resolved from the fd (darwin F_GETPATH, linux /proc/self/fd) and checked against the fd's inode; an unlinked log is still truncated, without a backup. No-op for journald, terminals, pipes, and platforms without fd->path mapping. Flags: -log-max-size (MB, default 50, 0 disables) and -log-max-backups (default 3); both also settable from config.json via ApplyToFlags. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 10 + cmd/daemon/main.go | 8 + internal/logcap/fdpath_darwin.go | 40 ++++ internal/logcap/fdpath_linux.go | 19 ++ internal/logcap/fdpath_other.go | 18 ++ internal/logcap/logcap.go | 267 +++++++++++++++++++++++++ internal/logcap/logcap_test.go | 333 +++++++++++++++++++++++++++++++ layers.yaml | 1 + 8 files changed, 696 insertions(+) create mode 100644 internal/logcap/fdpath_darwin.go create mode 100644 internal/logcap/fdpath_linux.go create mode 100644 internal/logcap/fdpath_other.go create mode 100644 internal/logcap/logcap.go create mode 100644 internal/logcap/logcap_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index df69010b..6c9e572c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,16 @@ 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.1.gz` … `daemon.log.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 under + systemd/journald or on a terminal. - **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 diff --git a/cmd/daemon/main.go b/cmd/daemon/main.go index 0c49688a..4a31e2d6 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, when stderr is a regular file (e.g. launchd's daemon.log); copy-truncate with gzipped backups. 0 disables") + logMaxBackups := flag.Int("log-max-backups", 3, "gzipped generations kept by -log-max-size rotation (.1.gz ... .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") @@ -220,6 +223,11 @@ 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). Lives for + // the daemon's lifetime; process exit stops it. + logcap.Watch(context.Background(), os.Stderr, int64(*logMaxSize)<<20, *logMaxBackups, time.Minute) // Sandbox: validate all configured file paths are under the confinement // root before the daemon touches the filesystem. Network paths are unaffected. 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/logcap.go b/internal/logcap/logcap.go new file mode 100644 index 00000000..55abfa3c --- /dev/null +++ b/internal/logcap/logcap.go @@ -0,0 +1,267 @@ +// 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 .1, truncate the original +// through the daemon's own descriptor, then gzip the copy into +// .1.gz, shifting older generations up to .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. +// +// 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" + "log/slog" + "os" + "time" +) + +// 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 +} + +// New returns a Rotator that rotates f once it exceeds maxBytes, keeping +// maxBackups gzipped generations (0 = truncate without keeping any). +func New(f *os.File, maxBytes int64, maxBackups int) *Rotator { + if maxBackups < 0 { + maxBackups = 0 + } + return &Rotator{file: f, maxBytes: maxBytes, maxBackups: maxBackups} +} + +// Watch checks f every interval until ctx is done, rotating it whenever it +// has grown past maxBytes. It returns false, starting nothing, when +// capping is disabled (maxBytes <= 0), f is not a regular file, or the +// platform cannot map a descriptor back to its path. +func Watch(ctx context.Context, f *os.File, maxBytes int64, maxBackups int, interval time.Duration) bool { + if maxBytes <= 0 || !fdPathSupported { + return false + } + if fi, err := f.Stat(); err != nil || !fi.Mode().IsRegular() { + return false + } + r := New(f, maxBytes, maxBackups) + go r.run(ctx, interval) + return true +} + +func (r *Rotator) run(ctx context.Context, interval time.Duration) { + ticker := time.NewTicker(interval) + defer ticker.Stop() + for { + // Check first so a log already over the limit at startup is + // rotated right away rather than an interval later. + if rotated, err := r.Check(); err != nil { + if rotated { + slog.Warn("log truncated without keeping a backup", "err", err) + } else { + slog.Warn("log rotation failed", "err", err) + } + } + select { + case <-ctx.Done(): + return + case <-ticker.C: + } + } +} + +// 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, renamed away): still + // truncate — capping disk use is the point — without a backup. + backupErr = err + } + + staged := "" + if src != nil { + if r.maxBackups > 0 { + finishInterrupted(path) + shiftBackups(path, r.maxBackups) + staged = path + ".1" + if err := copyTo(src, staged); err != nil { + backupErr = fmt.Errorf("copy log to %s: %w", staged, err) + _ = os.Remove(staged) + staged = "" + } + } + _ = src.Close() + } + + if err := truncate(r.file); err != nil { + if staged != "" { + // Keep the next round from compressing a duplicate. + _ = os.Remove(staged) + } + return false, fmt.Errorf("truncate log: %w", err) + } + + backup := "" + if staged != "" { + backup = path + ".1.gz" + if err := compress(staged, backup); err != nil { + backupErr = fmt.Errorf("compress %s: %w", staged, err) + backup = "" + } + } + slog.Info("log rotated", + "path", path, + "size_bytes", fi.Size(), + "max_bytes", r.maxBytes, + "backup", backup) + return true, backupErr +} + +// 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. +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.Open(path) + 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 +} + +// 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) +} + +func backupName(path string, gen int) string { + return fmt.Sprintf("%s.%d.gz", path, gen) +} + +// shiftBackups frees the .1.gz slot: the oldest generation is +// dropped and each remaining one moves up by one. Generations beyond keep +// (left from a larger -log-max-backups) are removed too. +func shiftBackups(path string, keep int) { + for gen := keep + 1; ; gen++ { + if err := os.Remove(backupName(path, gen)); err != nil { + break + } + } + _ = os.Remove(backupName(path, keep)) + for gen := keep - 1; gen >= 1; gen-- { + _ = os.Rename(backupName(path, gen), backupName(path, gen+1)) + } +} + +// finishInterrupted compresses a .1 left by a rotation that stopped +// between the copy and the compress (crash, kill). Its slot is free: the +// shift that preceded the copy already moved the old .1.gz up. +func finishInterrupted(path string) { + staged := path + ".1" + if _, err := os.Lstat(staged); err != nil { + return + } + if err := compress(staged, backupName(path, 1)); err != nil { + slog.Warn("log rotation: could not finish interrupted backup", "path", staged, "err", err) + } +} + +// copyTo copies src (from its current offset to EOF) into a new file at +// dst, replacing any existing one. +func copyTo(src *os.File, dst string) 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_TRUNC, 0o600) + if err != nil { + return err + } + if _, err := io.Copy(out, src); err != nil { + _ = out.Close() + return err + } + return out.Close() +} + +// compress gzips src into dst (via a temp file, so a partial dst never +// appears) and removes src. +func compress(src, dst string) (err error) { + // #nosec G304 -- src is derived from the daemon's own log path. + in, err := os.Open(src) + if err != nil { + return err + } + defer in.Close() + + tmp := dst + ".tmp" + // #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_TRUNC, 0o600) + if err != nil { + return err + } + defer func() { + if err != nil { + _ = os.Remove(tmp) + } + }() + zw := gzip.NewWriter(out) + _, copyErr := io.Copy(zw, in) + if err = errors.Join(copyErr, zw.Close(), out.Close()); err != nil { + return err + } + if err = os.Rename(tmp, dst); err != nil { + return err + } + return os.Remove(src) +} diff --git a/internal/logcap/logcap_test.go b/internal/logcap/logcap_test.go new file mode 100644 index 00000000..dc14be08 --- /dev/null +++ b/internal/logcap/logcap_test.go @@ -0,0 +1,333 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package logcap + +import ( + "compress/gzip" + "context" + "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 +} + +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, 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(path + ".1.gz") { + 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, 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, path+".1.gz"); got != first { + t.Fatalf("backup content mismatch: got %d bytes, want %d", len(got), len(first)) + } + if exists(path + ".1") { + t.Fatal("uncompressed staging copy left behind") + } + fi, err := os.Stat(path + ".1.gz") + 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, 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, 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, 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(path+".1", []byte("interrupted\n"), 0o600); err != nil { + t.Fatal(err) + } + write(t, f, strings.Repeat("n", 50)) + mustRotate(t, New(f, 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(path + ".1") { + t.Fatal("staging copy left behind") + } +} + +// 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, 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, 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, 10, 1)) + if !exists(moved + ".1.gz") { + 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, 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, 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, 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, 20, 1, 10*time.Millisecond) { + t.Fatal("Watch did not start on a regular file") + } + deadline := time.Now().Add(5 * time.Second) + for !exists(path + ".1.gz") { + if time.Now().After(deadline) { + t.Fatal("background watcher never rotated the log") + } + time.Sleep(10 * time.Millisecond) + } + cancel() + if got := gunzip(t, path+".1.gz"); got != content { + t.Fatalf("backup = %d bytes, want %d", len(got), len(content)) + } +} 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 From 332cc9d4aaa72ff3ddbd68fba37cc9c509e2d841 Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Thu, 24 Sep 2026 01:19:51 +0300 Subject: [PATCH 3/6] fix(logcap): touch only its own files; default-on only inside ~/.pilot Review findings on the log cap (#464): 1. It deleted other rotators' history. shiftBackups pruned every .N.gz up to the first gap, and finishInterrupted consumed any .1 as its own staging copy. Those are the names logrotate gives the same file (compress / delaycompress), so an operator with `rotate 7` lost generations 4-7 when the log first passed 50 MB. - Generations are now .pilot.N.gz, staged via .pilot.1, apart from logrotate's and newsyslog's names. - Within those names it reads, renames or removes only a regular file owned by the current user. Every kept slot is checked before the shift moves anything, and pruning stops at the first gap or foreign file. - Default scope: with the default -log-max-size, only a log inside ~/.pilot (or $PILOT_HOME/.pilot) is rotated, which covers launchd's daemon.log and pilotctl's pilot-.log. A log elsewhere is rotated only when -log-max-size is set explicitly, on the command line or in config.json. ApplyToFlags does not mark flags it sets, so the config map is checked directly. A watched log that moves out of scope stops being rotated. 2. It followed planted symlinks. .1 and .1.gz.tmp were opened O_CREATE|O_TRUNC and the staged copy was read through os.Open. In a directory another user can write to, that allowed arbitrary overwrite as the daemon user, or gzipping identity.json into the backup chain. - Staging and temp files are created O_CREATE|O_EXCL|O_NOFOLLOW. A stale temp is removed first only if it is ours. - Everything read back is opened O_NOFOLLOW and must be a regular file owned by the current uid. The live log itself is opened O_NOFOLLOW and must be the same file as our descriptor. - If the log's directory is writable by group or others (sticky /tmp included), or owned by another non-root user, rotation only truncates and creates no files. - A rename never replaces a file that is not ours. Tests: - logrotate/newsyslog/dateext files are preserved. - Symlinks at the legacy names (.1, .1.gz.tmp) and at every logcap name are not followed, and are left in place. - A .pilot.1 link to a secret is not consumed. - Other users' files at each name are left untouched: simulated through an ownership hook, and with real chown when the tests run as root (linux container). - Shared and foreign-owned directories only truncate. - Scope checks: Watch within, nested, via a symlinked dir; out of scope; a log that leaves scope. - flagExplicit and pilotDirs. Mutation-checked: disabling each guard fails at least one test. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 17 +- cmd/daemon/logrotation.go | 54 +++ cmd/daemon/logrotation_test.go | 71 ++++ cmd/daemon/main.go | 18 +- internal/logcap/logcap.go | 373 ++++++++++++++---- internal/logcap/logcap_safety_test.go | 545 ++++++++++++++++++++++++++ internal/logcap/logcap_test.go | 50 +-- internal/logcap/owner_other.go | 14 + internal/logcap/owner_unix.go | 23 ++ 9 files changed, 1063 insertions(+), 102 deletions(-) create mode 100644 cmd/daemon/logrotation.go create mode 100644 cmd/daemon/logrotation_test.go create mode 100644 internal/logcap/logcap_safety_test.go create mode 100644 internal/logcap/owner_other.go create mode 100644 internal/logcap/owner_unix.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 6c9e572c..47c67f96 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,11 +15,22 @@ Detailed per-release notes are on the 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.1.gz` … `daemon.log.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 + `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 under systemd/journald or on a terminal. + - By default only a log inside `~/.pilot` is rotated — where launchd and + `pilotctl daemon start` put it (also `$PILOT_HOME/.pilot`). 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. + - 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 the + log's directory is writable by group or others, or owned by another + user, it only truncates and keeps no 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 diff --git a/cmd/daemon/logrotation.go b/cmd/daemon/logrotation.go new file mode 100644 index 00000000..fb48256b --- /dev/null +++ b/cmd/daemon/logrotation.go @@ -0,0 +1,54 @@ +// 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). 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 +} + +// 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..bdd63e47 --- /dev/null +++ b/cmd/daemon/logrotation_test.go @@ -0,0 +1,71 @@ +// SPDX-License-Identifier: AGPL-3.0-or-later + +package main + +import ( + "flag" + "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) + } +} diff --git a/cmd/daemon/main.go b/cmd/daemon/main.go index 4a31e2d6..768ca5ba 100644 --- a/cmd/daemon/main.go +++ b/cmd/daemon/main.go @@ -115,8 +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, when stderr is a regular file (e.g. launchd's daemon.log); copy-truncate with gzipped backups. 0 disables") - logMaxBackups := flag.Int("log-max-backups", 3, "gzipped generations kept by -log-max-size rotation (.1.gz ... .N.gz); 0 keeps none") + 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 inside ~/.pilot is rotated (launchd's daemon.log, pilotctl's pilot-.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") @@ -159,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 { @@ -225,9 +227,15 @@ func main() { 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). Lives for - // the daemon's lifetime; process exit stops it. - logcap.Watch(context.Background(), os.Stderr, int64(*logMaxSize)<<20, *logMaxBackups, time.Minute) + // stderr isn't a regular file (journald, a terminal, a pipe), and by + // default for a log outside ~/.pilot, 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(), + }, time.Minute) // Sandbox: validate all configured file paths are under the confinement // root before the daemon touches the filesystem. Network paths are unaffected. diff --git a/internal/logcap/logcap.go b/internal/logcap/logcap.go index 55abfa3c..afb602b0 100644 --- a/internal/logcap/logcap.go +++ b/internal/logcap/logcap.go @@ -10,14 +10,32 @@ // 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 .1, truncate the original -// through the daemon's own descriptor, then gzip the copy into -// .1.gz, shifting older generations up to .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 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. +// +// 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 group or others, 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. +// +// Options.Anywhere and Options.Within set where it applies: the daemon +// rotates by default only a log inside ~/.pilot, where launchd and +// `pilotctl daemon start` put it, 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 @@ -30,40 +48,77 @@ import ( "errors" "fmt" "io" + "io/fs" "log/slog" "os" + "path/filepath" "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) is rotated, so + // the zero Options rotate nothing. + Anywhere bool + Within []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 } -// New returns a Rotator that rotates f once it exceeds maxBytes, keeping -// maxBackups gzipped generations (0 = truncate without keeping any). -func New(f *os.File, maxBytes int64, maxBackups int) *Rotator { - if maxBackups < 0 { - maxBackups = 0 +// 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, } - return &Rotator{file: f, maxBytes: maxBytes, maxBackups: maxBackups} } +// errOutOfScope reports a log outside the directories rotation is +// limited to (Options.Within). +var errOutOfScope = errors.New("log is outside the directories rotation is limited to") + // Watch checks f every interval until ctx is done, rotating it whenever it -// has grown past maxBytes. It returns false, starting nothing, when -// capping is disabled (maxBytes <= 0), f is not a regular file, or the -// platform cannot map a descriptor back to its path. -func Watch(ctx context.Context, f *os.File, maxBytes int64, maxBackups int, interval time.Duration) bool { - if maxBytes <= 0 || !fdPathSupported { +// has grown past opts.MaxBytes. 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 } - if fi, err := f.Stat(); err != nil || !fi.Mode().IsRegular() { + fi, err := f.Stat() + if err != nil || !fi.Mode().IsRegular() { return false } - r := New(f, maxBytes, maxBackups) + 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 } @@ -74,12 +129,17 @@ 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. - if rotated, err := r.Check(); err != nil { - if rotated { - slog.Warn("log truncated without keeping a backup", "err", err) - } else { - slog.Warn("log rotation failed", "err", err) - } + rotated, err := r.Check() + 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 + case rotated: + slog.Warn("log truncated without keeping a backup", "err", err) + default: + slog.Warn("log rotation failed", "err", err) } select { case <-ctx.Done(): @@ -107,22 +167,20 @@ 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, renamed away): still - // truncate — capping disk use is the point — without a backup. + // 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) } staged := "" if src != nil { if r.maxBackups > 0 { - finishInterrupted(path) - shiftBackups(path, r.maxBackups) - staged = path + ".1" - if err := copyTo(src, staged); err != nil { - backupErr = fmt.Errorf("copy log to %s: %w", staged, err) - _ = os.Remove(staged) - staged = "" - } + staged, backupErr = stage(src, path, r.maxBackups) } _ = src.Close() } @@ -137,7 +195,7 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { backup := "" if staged != "" { - backup = path + ".1.gz" + backup = backupName(path, 1) if err := compress(staged, backup); err != nil { backupErr = fmt.Errorf("compress %s: %w", staged, err) backup = "" @@ -153,7 +211,8 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { // 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. +// 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 { @@ -161,7 +220,7 @@ func (r *Rotator) openByPath(fi os.FileInfo) (string, *os.File, error) { } // #nosec G304 -- path is resolved from the daemon's own stderr // descriptor, not from any peer or user input. - src, err := os.Open(path) + src, err := os.OpenFile(path, os.O_RDONLY|oNoFollow, 0) if err != nil { return path, nil, err } @@ -173,6 +232,64 @@ func (r *Rotator) openByPath(fi os.FileInfo) (string, *os.File, error) { 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) +} + +// inScope reports whether path 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 { + 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 + } +} + +// 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, whose name it returns. An error +// means no backup is kept this round. +func stage(src *os.File, path string, keep int) (string, error) { + if err := checkDir(filepath.Dir(path)); err != nil { + return "", fmt.Errorf("keeping no backup: %w", err) + } + finishInterrupted(path) + if err := shiftBackups(path, keep); err != nil { + return "", fmt.Errorf("keeping no backup: %w", err) + } + staged := stagingName(path) + if err := copyTo(src, staged); err != nil { + return "", fmt.Errorf("copy log to %s: %w", staged, err) + } + return staged, 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 @@ -187,80 +304,192 @@ func truncate(f *os.File) error { 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.%d.gz", path, gen) + return fmt.Sprintf("%s.pilot.%d.gz", path, gen) +} + +// stagingName is the uncompressed copy a rotation gzips into generation 1. +func stagingName(path string) string { + return path + ".pilot.1" } -// shiftBackups frees the .1.gz slot: the oldest generation is +// ownerOf is fileOwner; tests swap it to simulate another user's files. +var ownerOf = fileOwner + +// 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 group or +// others — a sticky /tmp included, as the sticky bit stops removing +// others' names, not creating new ones — or one owned by another user +// (root excepted). +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()&0o022 != 0 { + return fmt.Errorf("log directory %s is writable by group or 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) + } + return nil +} + +// shiftBackups frees the .pilot.1.gz slot: the oldest generation is // dropped and each remaining one moves up by one. Generations beyond keep -// (left from a larger -log-max-backups) are removed too. -func shiftBackups(path string, keep int) { +// (left from a larger -log-max-backups) are removed too, up to the first +// gap. Every slot up to keep 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) error { + for gen := 1; gen <= keep; gen++ { + if _, err := lookup(backupName(path, gen)); err != nil { + return err + } + } for gen := keep + 1; ; gen++ { - if err := os.Remove(backupName(path, gen)); err != nil { + name := backupName(path, gen) + if exists, err := lookup(name); err != nil || !exists { + break + } + if err := os.Remove(name); err != nil { break } } - _ = os.Remove(backupName(path, keep)) + if err := os.Remove(backupName(path, keep)); err != nil && !errors.Is(err, fs.ErrNotExist) { + return err + } for gen := keep - 1; gen >= 1; gen-- { - _ = os.Rename(backupName(path, gen), backupName(path, gen+1)) + err := os.Rename(backupName(path, gen), backupName(path, gen+1)) + if err != nil && !errors.Is(err, fs.ErrNotExist) { + return err + } } + return nil } -// finishInterrupted compresses a .1 left by a rotation that stopped -// between the copy and the compress (crash, kill). Its slot is free: the -// shift that preceded the copy already moved the old .1.gz up. +// finishInterrupted compresses a .pilot.1 left by a rotation that +// stopped between the copy and the compress (crash, kill). Its slot is +// free: the shift that preceded the copy already moved the old +// .pilot.1.gz up. When it cannot, the staged copy stays where it is +// and this round keeps no backup (copyTo never replaces a file). func finishInterrupted(path string) { - staged := path + ".1" - if _, err := os.Lstat(staged); err != nil { + staged := stagingName(path) + exists, err := lookup(staged) + if err == nil && !exists { return } - if err := compress(staged, backupName(path, 1)); err != nil { + if err == nil { + err = compress(staged, backupName(path, 1)) + } + if err != nil { slog.Warn("log rotation: could not finish interrupted backup", "path", staged, "err", err) } } // copyTo copies src (from its current offset to EOF) into a new file at -// dst, replacing any existing one. +// dst. O_EXCL|O_NOFOLLOW: it never writes into an existing file or +// through a link, and removes only the file it created. func copyTo(src *os.File, dst string) 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_TRUNC, 0o600) + out, err := os.OpenFile(dst, os.O_WRONLY|os.O_CREATE|os.O_EXCL|oNoFollow, 0o600) if err != nil { return err } - if _, err := io.Copy(out, src); err != nil { - _ = out.Close() + _, err = io.Copy(out, src) + if err = errors.Join(err, out.Close()); err != nil { + _ = os.Remove(dst) return err } - return out.Close() + return nil } -// compress gzips src into dst (via a temp file, so a partial dst never -// appears) and removes src. -func compress(src, dst string) (err error) { - // #nosec G304 -- src is derived from the daemon's own log path. - in, err := os.Open(src) +// 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_TRUNC, 0o600) + out, err := os.OpenFile(tmp, os.O_WRONLY|os.O_CREATE|os.O_EXCL|oNoFollow, 0o600) if err != nil { return err } - defer func() { - if err != nil { - _ = os.Remove(tmp) - } - }() zw := gzip.NewWriter(out) _, copyErr := io.Copy(zw, in) - if err = errors.Join(copyErr, zw.Close(), out.Close()); err != nil { - return err + err = errors.Join(copyErr, zw.Close(), out.Close()) + if err == nil { + _, err = lookup(dst) } - if err = os.Rename(tmp, dst); err != nil { + 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_safety_test.go b/internal/logcap/logcap_safety_test.go new file mode 100644 index 00000000..e79a0973 --- /dev/null +++ b/internal/logcap/logcap_safety_test.go @@ -0,0 +1,545 @@ +// 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("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") + } +} + +// TestCheckKeepsNoBackupInSharedDirectory: where other users can create +// names — group- or world-writable, 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 + }{ + {"group-writable", 0o770, false}, + {"world-writable sticky", 0o777 | os.ModeSticky, false}, + {"another user's", 0o755, 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) + } + path := filepath.Join(dir, "daemon.log") + f := openLog(t, path) + writeFile(t, backupName(path, 1), "ours-1") + writeFile(t, stagingName(path), "ours-staged") + + write(t, f, strings.Repeat("f", 50)) + rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + want := []string{"daemon.log", filepath.Base(stagingName(path)), filepath.Base(backupName(path, 1))} + 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) + } + }) + } +} + +// 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) + } + } +} + +// 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 index dc14be08..05dd5a91 100644 --- a/internal/logcap/logcap_test.go +++ b/internal/logcap/logcap_test.go @@ -64,6 +64,12 @@ func exists(path string) bool { 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() @@ -80,7 +86,7 @@ func TestCheckBelowLimitIsNoop(t *testing.T) { f := openLog(t, path) write(t, f, strings.Repeat("x", 100)) - r := New(f, 100, 3) // exactly at the limit: not over it + 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) @@ -88,7 +94,7 @@ func TestCheckBelowLimitIsNoop(t *testing.T) { if got := readFile(t, path); len(got) != 100 { t.Fatalf("log size = %d, want 100 (untouched)", len(got)) } - if exists(path + ".1.gz") { + if exists(backupName(path, 1)) { t.Fatal("backup written for a log under the limit") } } @@ -99,19 +105,19 @@ func TestCheckRotatesTruncatesAndGzips(t *testing.T) { first := strings.Repeat("first line\n", 20) write(t, f, first) - r := New(f, 100, 3) + 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, path+".1.gz"); got != first { + 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(path + ".1") { + if exists(stagingName(path)) { t.Fatal("uncompressed staging copy left behind") } - fi, err := os.Stat(path + ".1.gz") + fi, err := os.Stat(backupName(path, 1)) if err != nil { t.Fatal(err) } @@ -130,7 +136,7 @@ func TestCheckRotatesTruncatesAndGzips(t *testing.T) { func TestCheckShiftsGenerationsAndDropsOldest(t *testing.T) { path := filepath.Join(t.TempDir(), "daemon.log") f := openLog(t, path) - r := New(f, 10, 3) + r := New(f, anywhere(10, 3)) contents := []string{"generation-A\n", "generation-B\n", "generation-C\n", "generation-D\n"} for _, c := range contents { @@ -159,7 +165,7 @@ func TestCheckRemovesGenerationsBeyondLoweredLimit(t *testing.T) { } } write(t, f, strings.Repeat("y", 50)) - mustRotate(t, New(f, 10, 2)) + mustRotate(t, New(f, anywhere(10, 2))) if !exists(backupName(path, 1)) || !exists(backupName(path, 2)) { t.Fatal("expected .1.gz and .2.gz") @@ -176,7 +182,7 @@ func TestCheckZeroBackupsJustTruncates(t *testing.T) { f := openLog(t, path) write(t, f, strings.Repeat("z", 50)) - mustRotate(t, New(f, 10, 0)) + mustRotate(t, New(f, anywhere(10, 0))) if got := readFile(t, path); got != "" { t.Fatalf("log not truncated: %d bytes", len(got)) } @@ -191,11 +197,11 @@ func TestCheckFinishesInterruptedRotation(t *testing.T) { 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(path+".1", []byte("interrupted\n"), 0o600); err != nil { + 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, 10, 3)) + 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) @@ -203,7 +209,7 @@ func TestCheckFinishesInterruptedRotation(t *testing.T) { if got := gunzip(t, backupName(path, 1)); got != strings.Repeat("n", 50) { t.Fatalf(".1.gz = %q, want the current log", got) } - if exists(path + ".1") { + if exists(stagingName(path)) { t.Fatal("staging copy left behind") } } @@ -220,7 +226,7 @@ func TestCheckNonAppendWriterRewinds(t *testing.T) { defer f.Close() write(t, f, strings.Repeat("w", 50)) - mustRotate(t, New(f, 10, 1)) + 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") @@ -239,7 +245,7 @@ func TestCheckTruncatesWithoutBackupWhenPathIsGone(t *testing.T) { t.Fatal(err) } - rotated, err := New(f, 10, 3).Check() + rotated, err := New(f, anywhere(10, 3)).Check() if !rotated { t.Fatalf("Check did not truncate an unlinked over-limit log (err %v)", err) } @@ -270,8 +276,8 @@ func TestCheckFollowsRenamedLog(t *testing.T) { t.Fatal(err) } - mustRotate(t, New(f, 10, 1)) - if !exists(moved + ".1.gz") { + mustRotate(t, New(f, anywhere(10, 1))) + if !exists(backupName(moved, 1)) { t.Fatal("backup not written next to the renamed log") } } @@ -286,7 +292,7 @@ func TestWatchNoopForNonRegularFiles(t *testing.T) { } defer pr.Close() defer pw.Close() - if Watch(ctx, pw, 1, 3, time.Minute) { + if Watch(ctx, pw, anywhere(1, 3), time.Minute) { t.Fatal("Watch started on a pipe (journald/systemd case)") } @@ -295,7 +301,7 @@ func TestWatchNoopForNonRegularFiles(t *testing.T) { t.Fatal(err) } defer devnull.Close() - if Watch(ctx, devnull, 1, 3, time.Minute) { + if Watch(ctx, devnull, anywhere(1, 3), time.Minute) { t.Fatal("Watch started on a character device (terminal case)") } } @@ -303,7 +309,7 @@ func TestWatchNoopForNonRegularFiles(t *testing.T) { func TestWatchDisabledByZeroLimit(t *testing.T) { path := filepath.Join(t.TempDir(), "daemon.log") f := openLog(t, path) - if Watch(context.Background(), f, 0, 3, time.Minute) { + if Watch(context.Background(), f, anywhere(0, 3), time.Minute) { t.Fatal("Watch started with maxBytes=0 (disabled)") } } @@ -316,18 +322,18 @@ func TestWatchRotatesInBackground(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - if !Watch(ctx, f, 20, 1, 10*time.Millisecond) { + 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(path + ".1.gz") { + 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, path+".1.gz"); got != content { + 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/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 +} From 5448deec893834e4bf1a669f1f8b493f554cdb15 Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Thu, 24 Sep 2026 01:58:08 +0300 Subject: [PATCH 4/6] fix(logcap): cap the brew services log; finish other logs' interrupted rotations Re-review findings on the log cap (#464): 1. `brew services` logs were still unbounded (464-R1). Pilot's Homebrew formula (TeoSlayer/homebrew-pilot) runs the daemon with log_path and error_log_path var/"log/pilot-daemon.log". launchd, or systemd with StandardOutput=append:, opens that file and nothing rotates it. It was outside the default scope, which was ~/.pilot only. - New logcap.Options.Files puts single log files in scope. A file matches by name in the same directory, with the directory compared by identity, so the rest of /var/log, which belongs to other formulae, stays out of scope. - The daemon adds /var/log/pilot-daemon.log when its executable resolves to /Cellar/pilotprotocol//bin/ pilot-daemon, the formula's binary, which the service runs through opt/pilotprotocol. Any other install is unchanged. - Flag help and CHANGELOG now name the Homebrew log. They no longer say "under systemd" for a no-op, since brew's systemd unit appends to a file. 2. Interrupted rotations of other logs were orphaned (464-R2). `pilotctl daemon start` names each daemon's log pilot-.log, so a .pilot.1 left by a daemon killed mid-rotation (up to the full log size, uncompressed) was under a name no later daemon looked at. - After its own rotation, a rotation now finishes the .pilot.1 copies in its directory into .pilot.1.gz. It acts only on regular files of ours; anything else is left alone. It does not shift or prune the other log's generations. - Liveness: a rotation holds an exclusive flock on its staged copy from creation until it is compressed. The lock is held through a second descriptor, so closing the writer still reports a delayed write error before the truncate. A copy that is locked belongs to a rotation in progress and is skipped. Death (SIGKILL, OOM) and exec release the lock. An empty copy of another log is skipped, because it may be in the instant between creation and lock. On a filesystem without flock, other logs' copies are skipped and the log's own rotation works as before. - A log's own leftover copy goes through the same lock. If a rotation in progress holds it, or it cannot be finished, this round keeps no backup and moves nothing. Before, the shift ran first and then failed on the occupied name, dropping the oldest generation for nothing. Not changed here: the formula's `keep_alive crashed: true` does not respawn the daemon after the watchdog's exit 86. That is pre-existing, and the fix belongs in the formula. Tests: - Files scope: the file itself, through a symlinked dir, and next to Within match; a neighbour, the same name in another dir or a subdir, and a missing dir do not. A renamed Files log stops being rotated. - homebrewServiceLog: the Cellar, opt and linked-bin paths map to var/log/pilot-daemon.log. ~/.pilot/bin, a manual install, another formula, another binary and a missing path do not. - Recovery: another log's copy is finished without shifting its generations. A locked copy is left until the lock goes away. Empty copies, links, directories, other users' files, a bare ".pilot.1", similar names and the parent directory are untouched. A locked own copy stops the shift. The lock is released every round. createStaged holds the lock until close. holdStaged yields a copy another rotation locked or replaced. The no-flock fallback is covered. - Cross-process: a helper process stages a copy and holds it. It is left alone while the helper lives; after SIGKILL it is finished. - Each new guard was mutation-checked: disabling it fails at least one test. Verified: go test (plain, and -race -short) for internal/logcap, cmd/daemon and pkg/daemon, plus ./tests shutdown and plugin subsets, on darwin. On linux/arm64 (container, root and uid 1000): internal/logcap and the cmd/daemon log tests. End to end with the real binaries: - A daemon in a fake Cellar, run through opt/ with a 55,000,000-byte var/log/pilot-daemon.log: rotated to 1,314 bytes plus .pilot.1.gz. The same log with a non-Cellar binary, and another var/log file, were untouched. - In a container: SIGKILL of a pilotctl-started daemon mid-rotation, then a second start. Pre-fix, pilot-24.log.pilot.1 (20 MB) stayed. Fixed, pilot-26.log.pilot.1 became pilot-26.log.pilot.1.gz (7,028,736 bytes uncompressed, the staged size). Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 23 +- cmd/daemon/logrotation.go | 49 +- cmd/daemon/logrotation_test.go | 61 +++ cmd/daemon/main.go | 8 +- internal/logcap/lock_other.go | 16 + internal/logcap/lock_unix.go | 38 ++ internal/logcap/logcap.go | 250 +++++++++-- internal/logcap/logcap_interrupted_test.go | 499 +++++++++++++++++++++ internal/logcap/logcap_safety_test.go | 83 +++- 9 files changed, 966 insertions(+), 61 deletions(-) create mode 100644 internal/logcap/lock_other.go create mode 100644 internal/logcap/lock_unix.go create mode 100644 internal/logcap/logcap_interrupted_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 47c67f96..85bb8eeb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,13 +18,22 @@ Detailed per-release notes are on the `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 under - systemd/journald or on a terminal. - - By default only a log inside `~/.pilot` is rotated — where launchd and - `pilotctl daemon start` put it (also `$PILOT_HOME/.pilot`). 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. + `~/.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 one in + that directory, including one left under a previous daemon's + `pilot-.log` name. A rotation holds its uncompressed copy + (`.pilot.1`) locked with `flock` until it is compressed, so a copy + another running daemon is still working on is left alone. - 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 diff --git a/cmd/daemon/logrotation.go b/cmd/daemon/logrotation.go index fb48256b..177e5542 100644 --- a/cmd/daemon/logrotation.go +++ b/cmd/daemon/logrotation.go @@ -13,9 +13,10 @@ import ( // 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). 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). +// 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 { @@ -27,6 +28,48 @@ func pilotDirs() []string { 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 diff --git a/cmd/daemon/logrotation_test.go b/cmd/daemon/logrotation_test.go index bdd63e47..f3b83f33 100644 --- a/cmd/daemon/logrotation_test.go +++ b/cmd/daemon/logrotation_test.go @@ -4,6 +4,7 @@ package main import ( "flag" + "os" "path/filepath" "reflect" "testing" @@ -69,3 +70,63 @@ func TestPilotDirs(t *testing.T) { 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 768ca5ba..8f563556 100644 --- a/cmd/daemon/main.go +++ b/cmd/daemon/main.go @@ -115,7 +115,7 @@ 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 inside ~/.pilot is rotated (launchd's daemon.log, pilotctl's pilot-.log); a log elsewhere only when this is set explicitly, here or in config.json. 0 disables") + 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)") @@ -228,13 +228,15 @@ func main() { // 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 outside ~/.pilot, which an operator may rotate by - // other means. Lives for the daemon's lifetime; process exit stops it. + // 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 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 index afb602b0..26053395 100644 --- a/internal/logcap/logcap.go +++ b/internal/logcap/logcap.go @@ -32,10 +32,19 @@ // truncates, so it creates nothing where someone else could have // planted a link. // -// Options.Anywhere and Options.Within set where it applies: the daemon -// rotates by default only a log inside ~/.pilot, where launchd and -// `pilotctl daemon start` put it, and a log elsewhere only when the -// operator asks for rotation explicitly. +// A rotation that dies between the copy and the compress (crash, kill) +// leaves .pilot.1 behind; the next rotation in that directory +// finishes it. That includes another log's copy: `pilotctl daemon start` +// names each daemon's log pilot-.log, so no later daemon writes to +// the name a crashed one staged under. 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 @@ -52,6 +61,7 @@ import ( "log/slog" "os" "path/filepath" + "strings" "time" ) @@ -64,10 +74,15 @@ type Options struct { // 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) is rotated, so - // the zero Options rotate nothing. + // 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 []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 @@ -78,6 +93,7 @@ type Rotator struct { maxBackups int anywhere bool within []string + files []string } // New returns a Rotator that rotates f once it exceeds opts.MaxBytes. @@ -92,13 +108,18 @@ func New(f *os.File, opts Options) *Rotator { maxBackups: backups, anywhere: opts.Anywhere, within: opts.Within, + files: opts.Files, } } -// errOutOfScope reports a log outside the directories rotation is -// limited to (Options.Within). +// 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") + // Watch checks f every interval until ctx is done, rotating it whenever it // has grown past opts.MaxBytes. It returns false, starting nothing, when // capping is disabled (MaxBytes <= 0), f is not a regular file, the @@ -177,27 +198,31 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { return false, fmt.Errorf("%w: %s", errOutOfScope, path) } - staged := "" + var staged *os.File if src != nil { if r.maxBackups > 0 { staged, 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 { - if staged != "" { + if staged != nil { // Keep the next round from compressing a duplicate. - _ = os.Remove(staged) + _ = os.Remove(staged.Name()) } return false, fmt.Errorf("truncate log: %w", err) } backup := "" - if staged != "" { + if staged != nil { backup = backupName(path, 1) - if err := compress(staged, backup); err != nil { - backupErr = fmt.Errorf("compress %s: %w", staged, err) + if err := compress(staged.Name(), backup); err != nil { + backupErr = fmt.Errorf("compress %s: %w", staged.Name(), err) backup = "" } } @@ -206,6 +231,10 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { "size_bytes", fi.Size(), "max_bytes", r.maxBytes, "backup", backup) + if staged != nil { + // After this log's own rotation, so the log is capped first. + finishOrphans(path) + } return true, backupErr } @@ -238,11 +267,11 @@ func namesFile(path string, fi os.FileInfo) bool { return err == nil && os.SameFile(fi, pfi) } -// inScope reports whether path lies inside one of r.within. Directories -// are compared by identity, so a symlinked ~/.pilot, or /var against -// macOS's /private/var, still matches. +// 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 { + if r.anywhere || r.isScopedFile(path) { return true } var roots []os.FileInfo @@ -271,23 +300,50 @@ func (r *Rotator) inScope(path string) bool { } } +// 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, whose name it returns. An error -// means no backup is kept this round. -func stage(src *os.File, path string, keep int) (string, error) { +// open at offset 0) to .pilot.1, which it returns open and locked +// for the caller to close once it is compressed. 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) (*os.File, error) { if err := checkDir(filepath.Dir(path)); err != nil { - return "", fmt.Errorf("keeping no backup: %w", err) + return nil, fmt.Errorf("keeping no backup: %w", err) + } + if err := finishStaged(path, false); err != nil { + return nil, fmt.Errorf("keeping no backup: finish interrupted rotation %s: %w", stagingName(path), err) } - finishInterrupted(path) if err := shiftBackups(path, keep); err != nil { - return "", fmt.Errorf("keeping no backup: %w", err) + return nil, fmt.Errorf("keeping no backup: %w", err) } staged := stagingName(path) - if err := copyTo(src, staged); err != nil { - return "", fmt.Errorf("copy log to %s: %w", staged, err) + held, err := createStaged(src, staged) + if err != nil { + return nil, fmt.Errorf("copy log to %s: %w", staged, err) } - return staged, nil + return held, nil } // truncate empties the log through the writer's own descriptor. @@ -310,14 +366,21 @@ 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 + ".pilot.1" + 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 + // 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 { @@ -418,40 +481,133 @@ func shiftBackups(path string, keep int) error { return nil } -// finishInterrupted compresses a .pilot.1 left by a rotation that -// stopped between the copy and the compress (crash, kill). Its slot is -// free: the shift that preceded the copy already moved the old -// .pilot.1.gz up. When it cannot, the staged copy stays where it is -// and this round keeps no backup (copyTo never replaces a file). -func finishInterrupted(path string) { - staged := stagingName(path) +// 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 + if err != nil || !exists { + return err } - if err == nil { - err = compress(staged, backupName(path, 1)) + 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 logs in +// path's directory (finishStaged). `pilotctl daemon start` 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. 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 finish interrupted backup", "path", staged, "err", err) + 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 || 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) + } } } -// copyTo copies src (from its current offset to EOF) into a new file at -// dst. O_EXCL|O_NOFOLLOW: it never writes into an existing file or -// through a link, and removes only the file it created. -func copyTo(src *os.File, dst string) error { +// 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 err + 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) - return err + _ = held.Close() + return nil, err } - return nil + 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 diff --git a/internal/logcap/logcap_interrupted_test.go b/internal/logcap/logcap_interrupted_test.go new file mode 100644 index 00000000..630ec42c --- /dev/null +++ b/internal/logcap/logcap_interrupted_test.go @@ -0,0 +1,499 @@ +// 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 +} + +// 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, anywhere(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, anywhere(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, anywhere(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 +// ".pilot.1" names; everything else in the directory — a link, a +// directory, another user's file, a bare ".pilot.1", other rotators' +// names — 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, "linked.log")) + symlink(t, secret, link) + if err := os.Mkdir(stagingName(filepath.Join(dir, "dir.log")), 0o700); err != nil { + t.Fatal(err) + } + theirs := stagingName(filepath.Join(dir, "theirs.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", + } + for name, content := range untouched { + writeFile(t, name, content) + } + 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, anywhere(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) + } + want := append([]string{"daemon.log", filepath.Base(backupName(path, 1))}, before...) + 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) + } +} + +// 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, anywhere(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, anywhere(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 index e79a0973..61300991 100644 --- a/internal/logcap/logcap_safety_test.go +++ b/internal/logcap/logcap_safety_test.go @@ -384,10 +384,12 @@ func TestCheckKeepsNoBackupInSharedDirectory(t *testing.T) { 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)) rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) - want := []string{"daemon.log", filepath.Base(stagingName(path)), filepath.Base(backupName(path, 1))} + 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) @@ -492,6 +494,85 @@ func TestWatchScopedToWithinDirs(t *testing.T) { } } +// 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. From 27e4be34b23dfc96ff11e3a8627f88873592b42f Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Thu, 24 Sep 2026 03:11:49 +0300 Subject: [PATCH 5/6] fix(logcap): keep backups in a directory group-writable only by the user's private group On Debian/Ubuntu and Fedora/RHEL every user has a private group and the login umask is 002, so install.sh's `mkdir -p ~/.pilot/bin` leaves ~/.pilot at 0775 with that group, and Linuxbrew's var/log likewise. checkDir refused any group write bit, so the default-on rotation there truncated the whole log and kept no backup, every time it passed 50 MB. checkDir now refuses a directory writable by others, owned by another user (root excepted), or writable by a group other than the user's own private group. A group counts as private (group_linux.go, from /etc/passwd and /etc/group) only when it is the account's primary group, carries the account's name (the test RHEL's bashrc uses to apply umask 002), no other account has it as primary group and it lists no other member, and the directory has no POSIX access ACL (with one, the group bits are the mask and a named entry may hold the write). Anything the files do not show to be that (an LDAP account, NIS compat entries, a line it cannot parse) counts as shared, which is the old behaviour. macOS has no user private groups (staff is every local account's primary group) and keeps the old check. TestMain runs the logcap tests under umask 022: under umask 002 on macOS, t.TempDir's directories are group-writable by staff and the tests unrelated to permissions failed. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 10 +- internal/logcap/group.go | 99 ++++++++++++++++++++ internal/logcap/group_linux.go | 48 ++++++++++ internal/logcap/group_linux_test.go | 126 ++++++++++++++++++++++++++ internal/logcap/group_other.go | 14 +++ internal/logcap/group_test.go | 59 ++++++++++++ internal/logcap/logcap.go | 32 +++++-- internal/logcap/logcap_safety_test.go | 90 ++++++++++++++++-- internal/logcap/main_unix_test.go | 21 +++++ 9 files changed, 478 insertions(+), 21 deletions(-) create mode 100644 internal/logcap/group.go create mode 100644 internal/logcap/group_linux.go create mode 100644 internal/logcap/group_linux_test.go create mode 100644 internal/logcap/group_other.go create mode 100644 internal/logcap/group_test.go create mode 100644 internal/logcap/main_unix_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 85bb8eeb..528a80db 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,9 +37,13 @@ Detailed per-release notes are on the - 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 the - log's directory is writable by group or others, or owned by another - user, it only truncates and keeps no backups. + 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 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/logcap.go b/internal/logcap/logcap.go index 26053395..c4d002ff 100644 --- a/internal/logcap/logcap.go +++ b/internal/logcap/logcap.go @@ -27,10 +27,10 @@ // 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 group or others, 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. +// 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 in that directory @@ -381,6 +381,10 @@ 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 { @@ -427,10 +431,15 @@ func openOurs(name string) (*os.File, error) { } // checkDir refuses a directory where another user could have planted a -// link or a file at one of logcap's names: one writable by group or -// others — a sticky /tmp included, as the sticky bit stops removing -// others' names, not creating new ones — or one owned by another user -// (root excepted). +// 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 { @@ -439,12 +448,15 @@ func checkDir(dir string) error { if !fi.IsDir() { return fmt.Errorf("%s is not a directory", dir) } - if fi.Mode().Perm()&0o022 != 0 { - return fmt.Errorf("log directory %s is writable by group or others", 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 } diff --git a/internal/logcap/logcap_safety_test.go b/internal/logcap/logcap_safety_test.go index 61300991..30d8ada9 100644 --- a/internal/logcap/logcap_safety_test.go +++ b/internal/logcap/logcap_safety_test.go @@ -355,18 +355,44 @@ func TestCheckReplacesItsOwnStaleTemp(t *testing.T) { } } +// 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 — group- or world-writable, sticky /tmp included — or in another -// user's directory, rotation only truncates and creates nothing. +// 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 + name string + mode os.FileMode + foreign bool + privateGroup bool }{ - {"group-writable", 0o770, false}, - {"world-writable sticky", 0o777 | os.ModeSticky, false}, - {"another user's", 0o755, true}, + {"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") @@ -380,6 +406,7 @@ func TestCheckKeepsNoBackupInSharedDirectory(t *testing.T) { 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") @@ -401,6 +428,53 @@ func TestCheckKeepsNoBackupInSharedDirectory(t *testing.T) { } } +// 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). 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()) +} From 9bb41da33690886b5a3d2cff485ecafb83effef1 Mon Sep 17 00:00:00 2001 From: Teodor Calin Date: Thu, 24 Sep 2026 04:01:01 +0300 Subject: [PATCH 6/6] fix(logcap): keep backups when the log cannot be truncated; finish only pilotctl's orphaned copies Two findings from the re-review of #464, both reproduced on d19db05. LOGCAP-1: rotate() shifted the generations, dropping the oldest, before it knew the truncate would work. On a log that cannot be truncated (an append-only file under chflags uappnd or chattr +a, or a filesystem that refuses ftruncate), each round deleted one backup and copied the whole log for nothing, every minute: [1,2,3] -> [2,3] -> [3] -> []. - shiftBackups parks the oldest generation at keep+1 instead of removing it. It is dropped once the log is truncated. When the truncate fails, unstage removes the copy and moves every generation back down, so nothing moves in a round that keeps no backup. If the copy cannot be removed, generation 1 stays free for a later round to finish it into, as before. - The pre-check now covers keep+1 as well, because the shift renames onto that slot. Something that is not ours there stops the backup with the generations intact. - run() waits twice as long after each round in a row that could not truncate the log, up to 64 intervals (about an hour). One that gets through resets the wait to the interval. The loop body moved into tick() so the schedule can be tested. LOGCAP-2: finishOrphans picked up every user-owned *.pilot.1 in the log's directory by name alone. So a rotation in a shared directory such as brew's var/log, or /var/log with an explicit -log-max-size, gzipped and unlinked another program's file, for example logrotate's delaycompress generation of a log named .pilot. - Orphans are finished only in a Within directory itself (~/.pilot, $PILOT_HOME/.pilot), where `pilotctl daemon start` puts its logs, and only under that command's per-daemon names, pilot-.log.pilot.1. These are the only logs that no later daemon rotates. Any other .pilot.1 is left alone. Tests: the generations and the log survive repeated truncate failures, for full sets of generations and for sets with gaps, via a read-only descriptor. On darwin, the reported chflags uappnd case is covered (EPERM). unstage leaves generation 1 free for a copy it cannot remove. The retryAfter and tick backoff schedule, including the reset, is covered, and so is another user's file in the parking slot. For orphans: only pilot-.log names are taken (app.pilot.1, pilot-daemon.log, pilot-starting.log and malformed pids are not), with a positive control. Nothing is finished for an explicit rotation outside Within, for the brew service log, or in a directory below ~/.pilot. The existing orphan tests now run in a Within directory. Each new guard was mutation-checked: disabling it fails at least one test. Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 17 +- cmd/pilotctl/main.go | 3 + internal/logcap/logcap.go | 250 ++++++++++++++++----- internal/logcap/logcap_darwin_test.go | 65 ++++++ internal/logcap/logcap_interrupted_test.go | 133 +++++++++-- internal/logcap/logcap_safety_test.go | 31 ++- internal/logcap/logcap_test.go | 155 +++++++++++++ 7 files changed, 579 insertions(+), 75 deletions(-) create mode 100644 internal/logcap/logcap_darwin_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 8cf71b93..096bc2cd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -29,11 +29,18 @@ Detailed per-release notes are on the 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 one in - that directory, including one left under a previous daemon's - `pilot-.log` name. A rotation holds its uncompressed copy - (`.pilot.1`) locked with `flock` until it is compressed, so a copy - another running daemon is still working on is left alone. + - 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 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/logcap.go b/internal/logcap/logcap.go index c4d002ff..7ec611e2 100644 --- a/internal/logcap/logcap.go +++ b/internal/logcap/logcap.go @@ -19,6 +19,12 @@ // 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 @@ -33,12 +39,17 @@ // 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 in that directory -// finishes it. That includes another log's copy: `pilotctl daemon start` -// names each daemon's log pilot-.log, so no later daemon writes to -// the name a crashed one staged under. 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. +// 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 — @@ -77,7 +88,10 @@ type Options struct { // 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 []string + // 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 @@ -94,6 +108,10 @@ type Rotator struct { 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. @@ -120,8 +138,17 @@ var errOutOfScope = errors.New("log is outside the directories rotation is limit // 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. It returns false, starting nothing, when +// 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). @@ -145,31 +172,56 @@ func Watch(ctx context.Context, f *os.File, opts Options, interval time.Duration } func (r *Rotator) run(ctx context.Context, interval time.Duration) { - ticker := time.NewTicker(interval) - defer ticker.Stop() for { // Check first so a log already over the limit at startup is // rotated right away rather than an interval later. - rotated, err := r.Check() - 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) + wait, ok := r.tick(interval) + if !ok { return - case rotated: - slog.Warn("log truncated without keeping a backup", "err", err) - default: - slog.Warn("log rotation failed", "err", err) } + timer := time.NewTimer(wait) select { case <-ctx.Done(): + timer.Stop() return - case <-ticker.C: + 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. @@ -199,9 +251,10 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { } var staged *os.File + var parked bool if src != nil { if r.maxBackups > 0 { - staged, backupErr = stage(src, path, r.maxBackups) + staged, parked, backupErr = stage(src, path, r.maxBackups) } _ = src.Close() } @@ -211,15 +264,16 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { } if err := truncate(r.file); err != nil { + err = fmt.Errorf("%w: %w", errTruncate, err) if staged != nil { - // Keep the next round from compressing a duplicate. - _ = os.Remove(staged.Name()) + err = errors.Join(err, unstage(path, r.maxBackups, parked)) } - return false, fmt.Errorf("truncate log: %w", err) + 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) @@ -231,13 +285,29 @@ func (r *Rotator) rotate(fi os.FileInfo) (bool, error) { "size_bytes", fi.Size(), "max_bytes", r.maxBytes, "backup", backup) - if staged != nil { + 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 @@ -267,6 +337,22 @@ func namesFile(path string, fi os.FileInfo) bool { 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. @@ -325,25 +411,31 @@ func (r *Rotator) isScopedFile(path string) bool { // 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. 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) (*os.File, error) { +// 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, fmt.Errorf("keeping no backup: %w", err) + return nil, false, fmt.Errorf("keeping no backup: %w", err) } if err := finishStaged(path, false); err != nil { - return nil, fmt.Errorf("keeping no backup: finish interrupted rotation %s: %w", stagingName(path), err) + return nil, false, fmt.Errorf("keeping no backup: finish interrupted rotation %s: %w", stagingName(path), err) } - if err := shiftBackups(path, keep); err != nil { - return nil, fmt.Errorf("keeping no backup: %w", 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) + held, err = createStaged(src, staged) if err != nil { - return nil, fmt.Errorf("copy log to %s: %w", staged, err) + dropParked(path, keep, parked) + return nil, false, fmt.Errorf("copy log to %s: %w", staged, err) } - return held, nil + return held, parked, nil } // truncate empties the log through the writer's own descriptor. @@ -460,16 +552,19 @@ func checkDir(dir string) error { return nil } -// shiftBackups frees the .pilot.1.gz slot: the oldest generation is -// dropped and each remaining one moves up by one. Generations beyond keep -// (left from a larger -log-max-backups) are removed too, up to the first -// gap. Every slot up to keep is checked before anything moves, so a name -// holding something that is not ours stops the shift with the +// 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) error { - for gen := 1; gen <= keep; gen++ { +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 err + return false, err } } for gen := keep + 1; ; gen++ { @@ -481,11 +576,27 @@ func shiftBackups(path string, keep int) error { break } } - if err := os.Remove(backupName(path, keep)); err != nil && !errors.Is(err, fs.ErrNotExist) { - return err - } - for gen := keep - 1; gen >= 1; gen-- { + 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 } @@ -493,6 +604,13 @@ func shiftBackups(path string, keep int) error { 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 @@ -537,11 +655,13 @@ func finishStaged(log string, orphan bool) error { return compress(staged, backupName(log, 1)) } -// finishOrphans finishes the interrupted rotations of the other logs in -// path's directory (finishStaged). `pilotctl daemon start` 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. Best effort: a -// copy it cannot finish stays for a later round. +// 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) @@ -552,7 +672,7 @@ func finishOrphans(path string) { own := filepath.Base(stagingName(path)) for _, e := range entries { log, ok := strings.CutSuffix(e.Name(), stagingSuffix) - if !ok || log == "" || e.Name() == own { + if !ok || !isDaemonStartLog(log) || e.Name() == own { continue } if err := finishStaged(filepath.Join(dir, log), true); err != nil && !errors.Is(err, errBusy) { @@ -561,6 +681,26 @@ func finishOrphans(path string) { } } +// 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 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 index 630ec42c..74773d5e 100644 --- a/internal/logcap/logcap_interrupted_test.go +++ b/internal/logcap/logcap_interrupted_test.go @@ -38,6 +38,13 @@ func holdLock(t *testing.T, path string) (release func()) { 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() @@ -72,7 +79,7 @@ func TestCheckFinishesAnotherLogsInterruptedRotation(t *testing.T) { f := openLog(t, path) content := strings.Repeat("pilot-40 line\n", 5) write(t, f, content) - mustRotate(t, New(f, anywhere(10, 3))) + 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) @@ -112,7 +119,7 @@ func TestCheckLeavesAnotherRotationInProgressAlone(t *testing.T) { path := filepath.Join(dir, "pilot-40.log") f := openLog(t, path) - r := New(f, anywhere(10, 3)) + 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" { @@ -141,7 +148,7 @@ func TestCheckLeavesEmptyStagedCopyOfAnotherLogAlone(t *testing.T) { path := filepath.Join(dir, "pilot-40.log") f := openLog(t, path) write(t, f, strings.Repeat("c", 50)) - mustRotate(t, New(f, anywhere(10, 3))) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) if !exists(stagingName(other)) { t.Fatal("empty staged copy removed") } @@ -151,10 +158,12 @@ func TestCheckLeavesEmptyStagedCopyOfAnotherLogAlone(t *testing.T) { } // TestCheckOnlyFinishesStagedCopiesOfOurs: the search for other logs' -// interrupted rotations touches only regular files of this user at -// ".pilot.1" names; everything else in the directory — a link, a -// directory, another user's file, a bare ".pilot.1", other rotators' -// names — is left as it was, and so is anything outside the directory. +// 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") @@ -167,12 +176,12 @@ func TestCheckOnlyFinishesStagedCopiesOfOurs(t *testing.T) { 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, "linked.log")) + link := stagingName(filepath.Join(dir, "pilot-1.log")) symlink(t, secret, link) - if err := os.Mkdir(stagingName(filepath.Join(dir, "dir.log")), 0o700); err != nil { + if err := os.Mkdir(stagingName(filepath.Join(dir, "pilot-2.log")), 0o700); err != nil { t.Fatal(err) } - theirs := stagingName(filepath.Join(dir, "theirs.log")) + theirs := stagingName(filepath.Join(dir, "pilot-3.log")) writeFile(t, theirs, "another user's file\n") fakeForeign(t, theirs) untouched := map[string]string{ @@ -183,15 +192,25 @@ func TestCheckOnlyFinishesStagedCopiesOfOurs(t *testing.T) { 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, anywhere(10, 3))) + mustRotate(t, New(f, pilotDir(dir, 10, 3))) for name, want := range untouched { if got := readFile(t, name); got != want { @@ -204,7 +223,16 @@ func TestCheckOnlyFinishesStagedCopiesOfOurs(t *testing.T) { if got := readFile(t, secret); got != "SECRET-KEY-MATERIAL\n" { t.Fatalf("link target changed: %q", got) } - want := append([]string{"daemon.log", filepath.Base(backupName(path, 1))}, before...) + 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) @@ -217,6 +245,83 @@ func TestCheckOnlyFinishesStagedCopiesOfOurs(t *testing.T) { } } +// 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 @@ -443,7 +548,7 @@ func TestCheckFinishesCopyOfKilledDaemon(t *testing.T) { path := filepath.Join(dir, "pilot-40.log") f := openLog(t, path) - r := New(f, anywhere(10, 3)) + r := New(f, pilotDir(dir, 10, 3)) write(t, f, strings.Repeat("h", 50)) mustRotate(t, r) if exists(backupName(dead, 1)) { @@ -483,7 +588,7 @@ func TestCheckWithoutFileLocking(t *testing.T) { content := strings.Repeat("k", 50) write(t, f, content) - mustRotate(t, New(f, anywhere(10, 3))) + 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) } diff --git a/internal/logcap/logcap_safety_test.go b/internal/logcap/logcap_safety_test.go index 30d8ada9..c18089a4 100644 --- a/internal/logcap/logcap_safety_test.go +++ b/internal/logcap/logcap_safety_test.go @@ -262,6 +262,32 @@ func TestCheckLeavesOtherUsersFilesAlone(t *testing.T) { } }) + 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") @@ -415,7 +441,10 @@ func TestCheckKeepsNoBackupInSharedDirectory(t *testing.T) { writeFile(t, orphan, "another log's staged copy") write(t, f, strings.Repeat("f", 50)) - rotateWithoutBackup(t, New(f, anywhere(10, 3)), path) + // 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) { diff --git a/internal/logcap/logcap_test.go b/internal/logcap/logcap_test.go index 05dd5a91..12e0643a 100644 --- a/internal/logcap/logcap_test.go +++ b/internal/logcap/logcap_test.go @@ -5,6 +5,8 @@ package logcap import ( "compress/gzip" "context" + "errors" + "fmt" "io" "os" "path/filepath" @@ -214,6 +216,159 @@ func TestCheckFinishesInterruptedRotation(t *testing.T) { } } +// 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.