appstore: messages carry a level, and a skipped dir is logged once

plugin/appstore/logging.go

@@ -0,0 +1,90 @@
+// SPDX-License-Identifier: AGPL-3.0-or-later
+
+package appstore
+
+import (
+	"context"
+	"fmt"
+	"log"
+	"log/slog"
+	"time"
+)
+
+// appLogger carries the app store's messages with a level: Printf for
+// routine ones, Warnf for problems an operator may need to act on. With
+// Config.Slog set they go to that logger (the daemon's log, where a reader
+// tells problems from routine by level); otherwise to the *log.Logger as
+// before, which has no levels.
+type appLogger struct {
+	std *log.Logger
+	sl  *slog.Logger
+}
+
+func newAppLogger(std *log.Logger, sl *slog.Logger) *appLogger {
+	return &appLogger{std: std, sl: sl}
+}
+
+// Printf logs a routine message (INFO).
+func (l *appLogger) Printf(format string, args ...any) {
+	l.logf(slog.LevelInfo, format, args...)
+}
+
+// Warnf logs a problem (WARN).
+func (l *appLogger) Warnf(format string, args ...any) {
+	l.logf(slog.LevelWarn, format, args...)
+}
+
+func (l *appLogger) logf(level slog.Level, format string, args ...any) {
+	if l.sl != nil {
+		l.sl.Log(context.Background(), level, "appstore: "+fmt.Sprintf(format, args...))
+		return
+	}
+	l.std.Printf(format, args...)
+}
+
+// warnOnce logs msg as a warning unless the last warning logged for key was
+// the same message, and reports whether it logged. For a condition the
+// rescan finds again on every tick: logged when it starts or changes, not
+// every few seconds. clearWarned forgets key once the condition is over, so
+// it is logged again if it comes back.
+func (s *supervisor) warnOnce(key, msg string) bool {
+	s.sigMu.Lock()
+	same := s.warned[key] == msg
+	s.warned[key] = msg
+	s.sigMu.Unlock()
+	if same {
+		return false
+	}
+	s.logger.Warnf("%s", msg)
+	return true
+}
+
+func (s *supervisor) clearWarned(key string) {
+	s.sigMu.Lock()
+	delete(s.warned, key)
+	s.sigMu.Unlock()
+}
+
+// markReinstalled and takeReinstalled carry watchSocket's "the install was
+// replaced" to the supervise loop, so that exit is not counted as a crash.
+func (s *supervisor) markReinstalled(id string) {
+	s.mu.Lock()
+	s.reinstalled[id] = true
+	s.mu.Unlock()
+}
+
+func (s *supervisor) takeReinstalled(id string) bool {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	r := s.reinstalled[id]
+	delete(s.reinstalled, id)
+	return r
+}
+
+// rescanInterval is how often run() rescans the install root.
+func (s *supervisor) rescanInterval() time.Duration {
+	if s.cfg.RescanInterval > 0 {
+		return s.cfg.RescanInterval
+	}
+	return defaultRescanInterval
+}

plugin/appstore/reap.go

@@ -177,6 +177,10 @@ func (s *supervisor) watchSocket(ctx context.Context, a *installedApp, pid int,
 	t := time.NewTicker(interval)
 	defer t.Stop()
 	seen := false
+	// The install dir as it was when this process started. pilotctl's
+	// install swaps in a new dir under the same path, which takes the
+	// socket path with it: that is a reinstall, not a lost socket.
+	origDir, _ := os.Stat(a.Dir)
 	for {
 		select {
 		case <-ctx.Done():
@@ -193,8 +197,14 @@ func (s *supervisor) watchSocket(ctx context.Context, a *installedApp, pid int,
 		case err == nil:
 			seen = true
 		case seen && os.IsNotExist(err):
-			s.logger.Printf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid)
-			s.writeAuditLine(a, auditEvent{Event: "socket-lost", PID: pid})
+			if cur, cerr := os.Stat(a.Dir); origDir != nil && cerr == nil && !os.SameFile(origDir, cur) {
+				s.logger.Printf("app=%s: reinstalled while running (pid=%d) — restarting it into the new install", a.Manifest.ID, pid)
+				s.writeAuditLine(a, auditEvent{Event: "reinstalled", PID: pid})
+				s.markReinstalled(a.Manifest.ID)
+			} else {
+				s.logger.Warnf("app=%s: socket %s vanished while pid=%d is running — restarting it", a.Manifest.ID, a.SocketPath, pid)
+				s.writeAuditLine(a, auditEvent{Event: "socket-lost", PID: pid})
+			}
 			if syscall.Kill(-pid, syscall.SIGTERM) != nil {
 				_ = syscall.Kill(pid, syscall.SIGTERM)
 			}

plugin/appstore/rlimit_linux.go

@@ -3,7 +3,6 @@
 package appstore
 
 import (
-	"log"
 	"syscall"
 	"unsafe"
 )
@@ -44,7 +43,7 @@ type rlimit64 struct {
 // There is a tiny race: between cmd.Start and prlimit landing, the
 // child can allocate. For an app starting from a clean state that's a
 // handful of fds / a small allocation — well under the caps.
-func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger) {
+func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *appLogger) {
 	setLimit := func(resource int, name string, val uint64) {
 		want := rlimit64{Cur: val, Max: val}
 		// SYS_PRLIMIT64 takes (pid, resource, *new_limit, *old_limit).
@@ -57,7 +56,7 @@ func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger
 			0, 0, 0,
 		)
 		if errno != 0 {
-			logger.Printf("prlimit pid=%d %s=%d: %v (proceeding; OS-wide ulimit still applies)", pid, name, val, errno)
+			logger.Warnf("prlimit pid=%d %s=%d: %v (proceeding; OS-wide ulimit still applies)", pid, name, val, errno)
 			return
 		}
 		logger.Printf("prlimit pid=%d %s=%d ok", pid, name, val)

plugin/appstore/rlimit_linux_test.go

@@ -43,7 +43,7 @@ func TestApplyChildResourceLimits_SetsAddressSpace(t *testing.T) {
 	cmd := startSleeper(t)
 	pid := cmd.Process.Pid
 	const limit uint64 = 2 << 30
-	applyChildResourceLimits(pid, limit, newQuietLogger(t))
+	applyChildResourceLimits(pid, limit, newAppLogger(newQuietLogger(t), nil))
 
 	if got := getChildRlimit(t, pid, syscall.RLIMIT_AS); got.Cur != limit {
 		t.Errorf("RLIMIT_AS Cur = %d, want %d", got.Cur, limit)
@@ -59,7 +59,7 @@ func TestApplyChildResourceLimits_ZeroSkipsAddressSpace(t *testing.T) {
 	cmd := startSleeper(t)
 	pid := cmd.Process.Pid
 	before := getChildRlimit(t, pid, syscall.RLIMIT_AS)
-	applyChildResourceLimits(pid, 0, newQuietLogger(t))
+	applyChildResourceLimits(pid, 0, newAppLogger(newQuietLogger(t), nil))
 	after := getChildRlimit(t, pid, syscall.RLIMIT_AS)
 	if after.Cur != before.Cur {
 		t.Errorf("RLIMIT_AS changed despite zero limit: before=%d after=%d", before.Cur, after.Cur)

plugin/appstore/rlimit_other.go

@@ -3,7 +3,6 @@
 package appstore
 
 import (
-	"log"
 	"sync"
 )
 
@@ -18,8 +17,8 @@ var resourceLimitWarning sync.Once
 //
 // The addrSpaceLimit parameter is accepted for signature parity with the
 // Linux build and ignored here.
-func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *log.Logger) {
+func applyChildResourceLimits(pid int, addrSpaceLimit uint64, logger *appLogger) {
 	resourceLimitWarning.Do(func() {
-		logger.Print("resource limits not enforced on this platform (linux-only); child file-descriptor and address-space caps are ignored")
+		logger.Printf("resource limits not enforced on this platform (linux-only); child file-descriptor and address-space caps are ignored")
 	})
 }

plugin/appstore/rlimit_other_test.go

@@ -17,7 +17,7 @@ func TestResourceLimitWarningOnce(t *testing.T) {
 	var wg sync.WaitGroup
 	for i := 0; i < 20; i++ {
 		wg.Add(1)
-		go func(pid int) { defer wg.Done(); applyChildResourceLimits(pid, 4<<30, logger) }(i)
+		go func(pid int) { defer wg.Done(); applyChildResourceLimits(pid, 4<<30, newAppLogger(logger, nil)) }(i)
 	}
 	wg.Wait()
 	if got := strings.Count(output.String(), "resource limits not enforced"); got != 1 {

plugin/appstore/service.go

@@ -15,6 +15,7 @@ import (
 	"errors"
 	"fmt"
 	"log"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"sync"
@@ -54,6 +55,12 @@ type Config struct {
 	// service logs via the standard log package.
 	Logger *log.Logger
 
+	// Slog, when set, receives the messages instead of Logger, with a
+	// level: INFO for routine ones, WARN for problems an operator may need
+	// to act on. The daemon passes its own logger, so these lines read and
+	// filter like the rest of its log.
+	Slog *slog.Logger
+
 	// RescanInterval controls how often the supervisor re-walks
 	// InstallRoot looking for newly-landed apps (e.g. dropped by
 	// `pilotctl appstore install` while the daemon is running).
@@ -106,7 +113,7 @@ func catalogPubkeyIsPlaceholder(pk []byte) bool {
 // Service implements coreapi.Service for the app store.
 type Service struct {
 	cfg     Config
-	logger  *log.Logger
+	logger  *appLogger
 	sup     *supervisor // started in Start; nil before then
 	cancel  context.CancelFunc
 	doneCh  chan struct{}
@@ -125,11 +132,11 @@ func NewService(cfg Config) *Service {
 	if cfg.CatalogPubkey == nil {
 		cfg.CatalogPubkey = EmbeddedCatalogPubkey
 	}
-	logger := cfg.Logger
-	if logger == nil {
-		logger = log.New(os.Stderr, "appstore ", log.LstdFlags|log.Lmicroseconds)
+	std := cfg.Logger
+	if std == nil {
+		std = log.New(os.Stderr, "appstore ", log.LstdFlags|log.Lmicroseconds)
 	}
-	return &Service{cfg: cfg, logger: logger}
+	return &Service{cfg: cfg, logger: newAppLogger(std, cfg.Slog)}
 }
 
 // Name returns the plugin identifier reported to the runtime registry.
@@ -187,14 +194,14 @@ func (s *Service) Start(ctx context.Context, deps Deps) error {
 	// operator catch a misbuilt release before any user-visible
 	// install completes.
 	if catalogPubkeyIsPlaceholder(s.cfg.CatalogPubkey) {
-		s.logger.Printf("WARNING: dev-mode trust anchor — CatalogPubkey is the all-zeros placeholder; signed catalogs will NOT verify. Replace EmbeddedCatalogPubkey for production builds.")
+		s.logger.Warnf("WARNING: dev-mode trust anchor — CatalogPubkey is the all-zeros placeholder; signed catalogs will NOT verify. Replace EmbeddedCatalogPubkey for production builds.")
 	}
 
 	runCtx, cancel := context.WithCancel(ctx)
 	s.cancel = cancel
 	s.doneCh = make(chan struct{})
 
-	s.sup = newSupervisor(s.cfg, deps, s.logger)
+	s.sup = newSupervisor(s.cfg, deps, s.logger.std)
 	apps, err := s.sup.scanInstalled()
 	if err != nil {
 		cancel()
@@ -227,7 +234,7 @@ func (s *Service) Stop(ctx context.Context) error {
 		s.sup = nil
 		return nil
 	case <-ctx.Done():
-		s.logger.Printf("stop: ctx deadline reached before drain")
+		s.logger.Warnf("stop: ctx deadline reached before drain")
 		return ctx.Err()
 	}
 }