fix(daemon): graceful watchdog exit (no orphaned apps) + built-in log size cap

[TeoSlayer]

Problem

Two robustness issues found on a macOS laptop (v1.13.9, run by launchd with KeepAlive SuccessfulExit=false and StandardOutPath/StandardErrorPath = ~/.pilot/daemon.log):

1. Watchdog restarts orphan every app-store app. When the rx watchdog gives up on a wedged transport it called os.Exit(86) directly (pkg/daemon/rxwatchdog.go), so launchd respawns the daemon. os.Exit skips the graceful shutdown in cmd/daemon/main.go (d.Stop() → rt.StopPlugins()), and StopPlugins is what stops the app-store supervisor and terminates its child apps. The apps run in their own process group, so every such exit orphaned all of them: 94 copies of each of 12 apps (~2.8 GB RSS) built up in a week. The app store now reaps orphans at spawn (fix(supervisor): no orphaned app processes after a hard daemon exit app-store#38), but the daemon should not create them in the first place.
2. daemon.log grows forever. launchd never rotates StandardOutPath. The file had reached 22 MB, and a June log was 13 MB gzipped.

Fix

1. Watchdog exit goes through graceful shutdown (commit 1)

• pkg/daemon/exit.go: requestSupervisorExit(ExitRequest{Code, Reason}) hands the exit to a host handler installed with daemon.SetExitHandler. It first arms a 15 s hard deadline that calls os.Exit with the same code if the teardown hangs (a wedged transport can hang it). Only the first request in a process takes effect. With no handler installed (embedders, bare test daemons) it exits immediately, which is the old behavior.
• rxWatchdogExit (the existing test seam) now requests the graceful exit instead of calling os.Exit. Unchanged: recordRxWedgeExit still runs before the exit, the restart-loop breaker still applies, and the tunnel.rx_wedged_exit event is still published. The webhook plugin now gets a chance to deliver that event. After requesting the exit, the watchdog loop stops ticking, so a slow teardown can't escalate again and record a second exit against the breaker.
• cmd/daemon: the shutdown loop (moved into awaitShutdown) receives exit requests alongside SIGINT/SIGTERM/SIGHUP and fleet lifecycle requests. It runs the normal teardown (Daemon.Stop → StopPlugins, same order, same reasons) and then os.Exit(86), so launchd/systemd still see a non-zero exit and respawn. Daemon.Stop gets an 8 s budget; if it overruns, plugins are stopped anyway, so apps are still reaped before the deadline. Teardown then keeps waiting for Daemon.Stop as before.
• The two log.Fatalf calls that run after StartPlugins (plugin startup failure, d.Start failure) now stop plugins before exiting 1. StartAll leaves already-started plugins running, and a respawn loop would otherwise leak a fresh set of apps on every attempt.
• Also checked: pathwatch.go only borrows the swappable-seam pattern and never exits. The only other os.Exit in cmd/daemon/pkg/daemon is -version.

2. Built-in log size cap (commit 2)

• internal/logcap: when stderr (fd 2) is a regular file, it fstats it every minute. Past the limit it rotates copy-truncate style:

  1. copy the file to <path>.pilot.1
  2. truncate the original through the daemon's own descriptor (it rewinds the offset first, for writers that didn't open the file O_APPEND)
  3. gzip <path>.pilot.1 into <path>.pilot.1.gz, shifting older copies up to <path>.pilot.N.gz

  launchd and pilotctl daemon start open the log O_APPEND, and child processes share that open file description, so truncation is safe for every writer (slog, panics, app children).

• The path is resolved from the fd (darwin fcntl F_GETPATH via x/sys/unix, linux readlink /proc/self/fd/2) and checked against the fd's inode. An unlinked or renamed-away log is still truncated, but without a backup. Leftover .pilot.1 staging files from an interrupted rotation get finished, including another log's in the same directory (commit 4), and generations beyond the configured count are pruned.

• It does nothing when stderr isn't a regular file (systemd/journald, terminal, pipe) or on platforms without fd→path mapping.

• Scope (commits 3, 4): with the default -log-max-size, only a log Pilot set up is rotated. That means a log inside ~/.pilot (or $PILOT_HOME/.pilot), where install.sh's launchd daemon.log and pilotctl daemon start's pilot-<pid>.log live. It also covers the Homebrew service's <brew prefix>/var/log/pilot-daemon.log, when the daemon is the formula's binary (commit 4). A log anywhere else is rotated only when -log-max-size is set explicitly, on the command line or in config.json, so operators with their own rotation are unaffected. A watched log that is moved out of scope stops being rotated.

• Files it didn't create are left alone (commit 3):

  • The .pilot infix keeps its names apart from logrotate's and newsyslog's (<log>.1, <log>.N.gz, <log>.0.gz).
  • Within its own names it reads, renames or removes only a regular file owned by the current uid. A symlink or another user's file there stops that round's backup; the log is still truncated.
  • Staging and temp files are created O_EXCL|O_NOFOLLOW, and everything it reads is opened 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 (sticky /tmp included), is owned by another non-root user, or is writable by a group other than the user's own private group (commit 5).

• Flags: -log-max-size (MB, default 50, 0 disables) and -log-max-backups (default 3). Because config.ApplyToFlags maps config keys to flags generically, both can also be set from ~/.pilot/config.json (log_max_size, log_max_backups).

3. Re-review fixes (commit 4)

• brew services log: Pilot's formula (TeoSlayer/homebrew-pilot) runs the daemon with log_path/error_log_path var/"log/pilot-daemon.log". launchd, or systemd with StandardOutput=append:, opens that file and never rotates it. New logcap.Options.Files puts single files in scope. A file matches by name in the same directory, and the directory is compared by identity. The daemon adds <prefix>/var/log/pilot-daemon.log only when its executable resolves to <prefix>/Cellar/pilotprotocol/<ver>/bin/pilot-daemon. The rest of var/log (other formulae's logs) stays out of scope.
• Orphaned staging copies: pilotctl daemon start names each daemon's log pilot-<pid>.log. A <log>.pilot.1 left by a daemon killed mid-rotation was therefore under a name no later daemon looked at. After its own rotation, a rotation now finishes the other <log>.pilot.1 copies in its directory into <log>.pilot.1.gz. It acts only on regular files of ours, and does not shift or prune that log's generations.
  • To tell a dead rotation from a live one, 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 delayed write errors before the truncate. A locked copy is skipped. Death 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 behaves as before.
• A log's own leftover copy goes through the same lock. If a rotation in progress holds it, or it can't be finished, that round keeps no backup and moves nothing. Before, the shift ran first and dropped the oldest generation for nothing.
• Not changed here: the formula's keep_alive crashed: true means launchd does not respawn after the watchdog's exit 86. That is pre-existing, and the fix belongs in the formula.

4. Re-review fix (commit 5): user private groups

• Problem: on Debian/Ubuntu and Fedora/RHEL every user has a private group and the login umask is 002. install.sh's mkdir -p ~/.pilot/bin then makes ~/.pilot 0775 with that group, and Linuxbrew's var/log ends up the same. The directory check refused any group write bit. So in both places the default rotation truncated the whole log and kept no backup, each time it passed 50 MB.
• Fix: checkDir now refuses a directory that is writable by others (sticky /tmp included), owned by another user (root excepted), or writable by a group other users may be in. A group-writable directory is accepted only when its group is the user's own private group. On Linux (internal/logcap/group_linux.go, group.go), all of these must hold:
  • It is the primary group of the daemon's account in /etc/passwd.
  • In /etc/group it has the account's name. RHEL's /etc/bashrc uses the same test to decide on umask 002. It keeps out a shared group such as users that the account happens to be the only member of so far.
  • No other account has it as its primary group, and /etc/group lists no other member.
  • The directory has no POSIX access ACL. With an ACL, the group bits are the ACL mask, and a named entry may be what grants the write.
• Fails closed: anything the files don't show to be private counts as shared and keeps the previous behavior (truncate, no backup). That covers accounts or groups that exist only in LDAP/SSSD, NIS compat (+/-) entries, and lines it can't parse. Release binaries are built CGO_ENABLED=0, so the daemon could not see NSS sources beyond these files anyway.
• macOS is unchanged. It has no user private groups: staff is every local account's primary group, and accounts do not live in /etc/passwd or /etc/group. A group-writable directory there (umask 002 gives ~/.pilot 0775 user:staff) is really shared, so it still gets no backups. The default umask 022 gives 0755, which keeps backups.
• Why not the review's other two options:
  • Skipping truncation in such directories would bring back unbounded growth.
  • Making install.sh create ~/.pilot as 0700 would fix neither existing installs nor Linuxbrew's var/log.
• Test-only change: the internal/logcap tests now run under umask 022 (TestMain). Under umask 002 on macOS, t.TempDir() directories are group-writable by staff, and tests unrelated to permissions failed. The permission tests set their modes themselves.
• Merge: origin/main is merged in with no conflicts; the CHANGELOG merged automatically.

5. Re-review fixes (commit 6)

• A log that can't be truncated no longer loses its backups (LOGCAP-1). The shift used to drop the oldest generation before the truncate ran. On an append-only log (chflags uappnd, chattr +a) or a filesystem that refuses ftruncate, each round deleted one backup and then threw away its copy of the whole log. That happened every minute: [1,2,3] → [2,3] → [3] → [].

  • The shift now parks the oldest generation at .pilot.<keep+1>.gz. It is dropped only after the log is truncated.
  • If the truncate fails, the round's copy is removed and every generation moves back down, so nothing moves in a round that keeps no backup. If the copy can't be removed, generation 1 is left free for a later round to finish it into, which is the existing invariant.
  • The pre-check now also covers keep+1, because the shift renames onto that slot. Something that isn't ours there stops the backup with the generations intact.
  • The watcher backs off while truncation keeps failing. The wait doubles after each failed round, up to 64 intervals (about an hour at the daemon's 1-minute interval), and resets once a round gets through. Crash recovery is unchanged: a round that dies with a generation parked leaves it where the next round's pruning of generations beyond keep removes it.

• Other programs' *.pilot.1 files are left alone (LOGCAP-2). The orphan scan used to take any user-owned <x>.pilot.1 in the log's directory. In a shared directory (brew's var/log, or /var/log with an explicit -log-max-size) it gzipped and unlinked, for example, logrotate's delaycompress generation of a log named <x>.pilot.

  • Orphans are now finished only in a Within directory itself (~/.pilot, $PILOT_HOME/.pilot). That is where pilotctl daemon start writes logs.
  • They are finished only under that command's per-daemon names, pilot-<pid>.log.pilot.1, which are the only logs no later daemon rotates. A comment in cmd/pilotctl points back to the matcher.

• internal/logcap is added to the layers.yaml utilities list. CHANGELOG entries are added for both changes.

Tests

• pkg/daemon/zz_exit_request_test.go: an exit request reaches the handler without exiting the process; the deadline forces exit(86) when shutdown hangs; with no handler the process exits immediately; the first request wins; the real (unswapped) rxWatchdogExit records the exit and then requests a graceful shutdown with code 86. The existing watchdog tests (zz_rx_watchdog*_test.go) pass unchanged.

• cmd/daemon/shutdown_test.go: an exit request ends the loop and runs Daemon.Stop → StopPlugins → exit(86) in that order; SIGHUP reloads, and SIGTERM tears down without a forced exit; a fleet restart maps to re-exec; plugins are still stopped when Daemon.Stop hangs.

• internal/logcap/logcap_test.go: size threshold (at the limit it doesn't rotate), truncate + gzip + 0600 mode, generation shifting and dropping the oldest, pruning when the limit is lowered, maxBackups=0, finishing an interrupted rotation, rewind for non-append writers, unlinked log, renamed log, no-op for pipe and char device, disabled at 0, background Watch.

• internal/logcap/logcap_safety_test.go (commit 3):

  • logrotate, newsyslog and dateext files are preserved.
  • Symlinks at the old names (.1, .1.gz.tmp) and at every logcap name are not followed, and stay in place.
  • A .pilot.1 link to a secret file is not consumed.
  • Other users' files at each name are left untouched. This is simulated through an ownership hook, and uses real chown when run as root.
  • Directories writable by a shared group, sticky world-writable directories and foreign-owned directories only truncate.
  • Scope: inside, nested, a symlinked dir, outside, and a log that leaves scope.
  • Each guard was mutation-checked: disabling it fails at least one test.

  Passes on darwin and on linux (arm64 container, as root and as uid 1000).

• internal/logcap/logcap_interrupted_test.go (commit 4):

  • Another log's interrupted copy is finished without its generations being shifted.
  • A copy another rotation holds locked is left alone until the lock is released.
  • The scan leaves untouched: empty copies, links, directories, other users' files, a bare .pilot.1, look-alike names and the parent directory.
  • A locked own copy stops the shift, and 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.
  • A cross-process test: a helper process stages and holds a copy. The copy is left alone while the helper lives, and finished after SIGKILL.

• internal/logcap/logcap_safety_test.go (commit 4): Files scope (the file, a symlinked dir, a neighbour, the same name elsewhere or in a subdirectory, a missing dir). A renamed Files log stops being rotated.

• cmd/daemon/logrotation_test.go (commit 3): -log-max-size counts as explicit from the flag or from config.json (either key spelling, only with a value ApplyToFlags applies). Default scope directories are ~/.pilot and $PILOT_HOME/.pilot. Commit 4 adds homebrewServiceLog: the Cellar, opt and linked-bin paths map to var/log/pilot-daemon.log. Non-Homebrew installs, other formulae and other binaries map to nothing.

• GOWORK=off go build ./... (darwin, linux amd64/arm64), go vet on the touched packages, and go test ./pkg/daemon/ ./cmd/daemon/ ./internal/logcap/ (also with -race -short) plus ./tests -run 'TestDaemonShutdown|TestStreamLifecycleGoroutines|TestPluginShutdown' all pass. The baseline on main was also green.

• Manual smoke test: prefilled a 3 MB daemon.log, started the daemon with -log-max-size 1 -log-max-backups 2 and stderr appended to that file. The log was rotated right at startup (daemon.log.1.gz = 3,000,000 bytes uncompressed), the live log continued from 0, and the first line was the log rotated marker.

• Smoke test after commit 3 (real binary, throwaway HOME, over-limit logs):

  • Default settings, ~/.pilot/daemon.log: rotated into daemon.log.pilot.1.gz.
  • Default settings, log outside ~/.pilot: untouched.
  • log_max_size set in config.json, log outside: rotated.
  • Explicit flag next to logrotate's .1 and .2.gz–.5.gz: rotated, and all of those files survived.
  • Group-writable ~/.pilot (macOS, group staff): truncated, no backup, one warning.

• Smoke tests after commit 4:

  • Homebrew service log: the real binary in a fake Cellar, run through opt/pilotprotocol, with a 55,000,000-byte var/log/pilot-daemon.log. It was rotated to 1,314 bytes plus .pilot.1.gz (55,000,000 bytes uncompressed).
  • Two controls were untouched: the same log with a non-Cellar binary, and another var/log file.
  • Orphaned staging copy, in a linux container with the network off: pilotctl daemon start over a 400 MB log, SIGKILL during the first rotation, then a second start. Pre-fix, pilot-24.log.pilot.1 (20 MB) was never touched. With the fix, pilot-26.log.pilot.1 was finished into pilot-26.log.pilot.1.gz (7,028,736 bytes, the staged size).

• Every new guard in commit 4 was mutation-checked, too.

• Tests for commit 5:

  • internal/logcap/group_test.go (all platforms) tests userPrivateGroup directly.
    • Accepted: the user's private group, root's group, and a group that lists only the user.
    • Rejected: another user's group; a group that is not the account's primary group, including one named after the user; a shared users group with a single member; a group that lists another member; another account's primary group; a duplicate entry with a member; a group under a different name; a missing group or account; NIS compat lines; malformed lines; a non-numeric gid; empty files.
  • logcap_safety_test.go:
    • TestCheckKeepsBackupsInPrivateGroupDirectory: a 0775 private-group directory rotates normally. An interrupted round is finished, another log's orphaned copy is finished, and three rounds shift into .pilot.1.gz–.pilot.3.gz.
    • TestCheckKeepsNoBackupInSharedDirectory adds three cases: a shared group, a world-writable directory with a private group (sticky and not), and another user's directory with a private group.
  • group_linux_test.go (Linux, real /etc files):
    • TestCheckRealPrivateGroupDirectory: a directory made with mkdir under umask 002 keeps backups.
    • TestPrivateGroupDirWithACL: a POSIX ACL that grants another uid write makes the directory not private. The test sets system.posix_acl_access directly.
    • TestPrivateGroupDirOtherGroup (root only): a directory given another group is refused.
  • Mutation check: disabling any single guard fails at least one test. The guards are the name, member, other-primary, primary-gid, group-entry-required, ACL and o+w checks, plus the relaxation itself in both directions. The one exception is the explicit NIS-line check, which is defense in depth: a bare + line already fails the numeric parse.
  • macOS: GOWORK=off go test ./internal/logcap/ ./cmd/daemon/ ./pkg/daemon/ -count=1 passes after the merge. logcap and cmd/daemon also pass under umask 002, and logcap passes with -race.
  • Linux (golang:1.25 arm64, network off): logcap and cmd/daemon pass as root, as a private-group user u under umask 002 (the real-file tests run), and as a users-group user v under umask 002 (they skip). The real-chown test runs as root.

• Smoke tests after commit 5 (real binaries, default flags, 53 MB ~/.pilot/pilot-4242.log):

  • The finding's repro (ubuntu:24.04): su - u gets login umask 0002, and mkdir -p ~/.pilot/bin makes ~/.pilot drwxrwxr-x u:u. Over two daemon starts the log was rotated into .pilot.1.gz (53,003,015 bytes) and .pilot.2.gz (53,002,267 bytes), and the live log restarted at 748 bytes. Before this commit, the log was truncated with no backup.
  • golang:1.25:
    • Private-group user u: .pilot.1.gz was kept.
    • User v, whose primary group is users (0775 v:users): the log was truncated with no backup, with the WARN writable by a group other users may be in. That is correct, since users is a shared group.
  • macOS, throwaway HOME with group staff, darwin daemon:
    • umask 022: ~/.pilot is 0755, and .pilot.1.gz was kept (53,000,000 bytes).
    • umask 002: ~/.pilot is 0775 staff. The log was truncated with no backup, as before.

• Tests for commit 6:

  • TestCheckKeepsGenerationsWhenLogCannotBeTruncated covers full sets of generations and sets with gaps ({1,2,3}, {1,3}, {2,3}, {1}, {3}, none). The log is truncated through a read-only descriptor, which fails the same way on darwin and linux. After three failed rounds the directory is byte-for-byte unchanged. Once truncation works again, the rotation shifts exactly as it would have.
  • TestCheckKeepsGenerationsOfAppendOnlyLog (darwin) is the reported case: the log is made append-only with chflags uappnd, Check returns errTruncate wrapping EPERM, and every generation is kept.
  • TestUnstageLeavesGenerationOneFreeForACopyItCannotRemove: a copy that can't be removed keeps the shift, and only the parked generation is dropped.
  • TestRetryAfter and TestTickBacksOffWhileLogCannotBeTruncated check the waits (1, 2, 4 … 64, 64 intervals), the reset after a round that gets through, and the restart at 1 after the next failure.
  • TestCheckLeavesOtherUsersFilesAlone/in the slot the oldest is parked in: another user's file at .pilot.<keep+1>.gz stops the backup, and nothing moves.
  • TestCheckOnlyFinishesStagedCopiesOfOurs puts its link, directory and foreign-owner guard cases at pilot-<n>.log.pilot.1 names, so each guard still runs. It also adds the staging names of non-pilotctl logs (app.pilot.1, i.e. the reported case, plus x.log, pilot-daemon.log, pilot-starting.log, pilot-.log, pilot-12a.log) and a positive control that is finished.
  • TestCheckFinishesOrphansOnlyInPilotDirectory: 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.
  • Mutation check: disabling any single new guard fails at least one test. The guards are the unshift, dropping at shift time, the keep+1 pre-check, unshifting despite a failed remove, the drop after truncate, the backoff, its reset, tick's wait, the directory check (anywhere and nested), the name match and its prefix, suffix and digit checks, and the parked top slot.
  • macOS: GOWORK=off go test ./internal/logcap/ ./cmd/daemon/ -count=1 passes, and logcap also passes with -race and under umask 002. go build ./... and go vet pass for darwin and for linux amd64/arm64, and the logcap test binary compiles for linux. Linux runtime is covered by CI's ubuntu-latest job; the local Docker daemon was unresponsive this round.

Related: pilot-protocol/app-store#38

🤖 Generated with Claude Code