daemon, seclog: log snapd restarts outside requested restart and standby

daemon/daemon.go

@@ -672,6 +672,7 @@ func (d *Daemon) Stop(sigCh chan<- os.Signal) error {
 		return d.doReboot(sigCh, restart.RestartSystem, nil, immediateReboot, rebootRetryWaitTimeout)
 	}
 	if d.overlord == nil {
+		seclog.LogSystemRestartSnapd(d.Version, seclog.SnapdRestartStopFailed)
 		return fmt.Errorf("internal error: no Overlord")
 	}
 
@@ -784,10 +785,13 @@ func (d *Daemon) Stop(sigCh chan<- os.Signal) error {
 			// which will lead to confusing results.
 			if needsFullShutdown {
 				logger.Noticef("WARNING: cannot stop daemon: %v", err)
+			} else if snapdenv.Preseeding() {
+				// Preseed stops on the build host and does not restart.
+				return err
 			} else {
 				// Wait failed: this is an aborted shutdown, not a
-				// completed controlled restart or standby, so do
-				// not emit sys_restart_snapd or sys_standby_snapd.
+				// completed controlled restart or standby.
+				seclog.LogSystemRestartSnapd(d.Version, seclog.SnapdRestartStopFailed)
 				return err
 			}
 		}
@@ -798,7 +802,7 @@ func (d *Daemon) Stop(sigCh chan<- os.Signal) error {
 	}
 
 	if restartType == restart.RestartDaemon {
-		seclog.LogSystemRestartSnapd(d.Version, restartReason)
+		seclog.LogSystemRestartSnapd(d.Version, string(restartReason))
 		if restartReason == "" {
 			logger.Noticef("restarting daemon")
 		} else {
@@ -816,7 +820,7 @@ func (d *Daemon) Stop(sigCh chan<- os.Signal) error {
 	}
 
 	if restartSocket {
-		seclog.LogSystemStandbySnapd(d.Version, restartReason)
+		seclog.LogSystemStandbySnapd(d.Version, string(restartReason))
 		if restartReason == "" {
 			logger.Noticef("entering standby")
 		} else {
@@ -825,6 +829,11 @@ func (d *Daemon) Stop(sigCh chan<- os.Signal) error {
 		return ErrRestartSocket
 	}
 
+	// Idle standby was requested but pending requests prevented it.
+	if restartType == restart.RestartSocket {
+		seclog.LogSystemRestartSnapd(d.Version, seclog.SnapdRestartIdleAborted)
+		logger.Noticef("restarting daemon (%s)", seclog.SnapdRestartIdleAborted)
+	}
 	return nil
 }
 

daemon/daemon_test.go

@@ -61,6 +61,7 @@ import (
 	"github.com/snapcore/snapd/seclog/seclogtest"
 	"github.com/snapcore/snapd/snap"
 	"github.com/snapcore/snapd/snap/snaptest"
+	"github.com/snapcore/snapd/snapdenv"
 	"github.com/snapcore/snapd/store"
 	"github.com/snapcore/snapd/systemd"
 	"github.com/snapcore/snapd/testutil"
@@ -852,6 +853,7 @@ func (s *daemonSuite) TestRestartDaemonAfterSocketStandby(c *check.C) {
 	c.Check(seclogBuf.String(), testutil.Contains, "Snapd restart with reason snapd-update")
 	c.Check(seclogBuf.String(), testutil.Contains, `[snapd_version="2.78"]`)
 	c.Check(seclogBuf.String(), check.Not(testutil.Contains), "sys_standby_snapd")
+	c.Check(seclogBuf.String(), check.Not(testutil.Contains), seclog.SnapdRestartIdleAborted)
 }
 
 func (s *daemonSuite) TestGracefulStop(c *check.C) {
@@ -1521,6 +1523,7 @@ func (s *daemonSuite) TestRestartIntoSocketModePendingChanges(c *check.C) {
 	defer restore()
 
 	d := s.newTestDaemon(c)
+	d.Version = "2.78"
 	makeDaemonListeners(c, d)
 
 	// mark as already seeded, we also have no snaps so this will
@@ -1556,7 +1559,87 @@ func (s *daemonSuite) TestRestartIntoSocketModePendingChanges(c *check.C) {
 	// when the daemon got a pending change it just restarts
 	err := d.Stop(nil)
 	c.Check(err, check.IsNil)
-	c.Check(seclogBuf.String(), check.Equals, "")
+	c.Check(seclogBuf.String(), testutil.Contains, "sys_restart_snapd")
+	c.Check(seclogBuf.String(), testutil.Contains, "Snapd restart with reason "+seclog.SnapdRestartIdleAborted)
+	c.Check(seclogBuf.String(), testutil.Contains, `[snapd_version="2.78"]`)
+	c.Check(seclogBuf.String(), testutil.Contains, `[reason="`+seclog.SnapdRestartIdleAborted+`"]`)
+	c.Check(seclogBuf.String(), check.Not(testutil.Contains), "sys_standby_snapd")
+}
+
+func (s *daemonSuite) TestStopNoOverlordLogsRestart(c *check.C) {
+	seclogBuf := &bytes.Buffer{}
+	seclog.Setup(seclogtest.MockSecurityLogger(seclogBuf))
+	defer seclog.Setup(seclog.NewNopLogger())
+
+	d := &Daemon{Version: "2.78"}
+	err := d.Stop(nil)
+	c.Check(err, check.ErrorMatches, "internal error: no Overlord")
+	c.Check(seclogBuf.String(), testutil.Contains, "sys_restart_snapd")
+	c.Check(seclogBuf.String(), testutil.Contains, "Snapd restart with reason "+seclog.SnapdRestartStopFailed)
+	c.Check(seclogBuf.String(), testutil.Contains, `[snapd_version="2.78"]`)
+	c.Check(seclogBuf.String(), testutil.Contains, `[reason="`+seclog.SnapdRestartStopFailed+`"]`)
+}
+
+func (s *daemonSuite) TestStopTombWaitLogsRestart(c *check.C) {
+	seclogBuf := &bytes.Buffer{}
+	seclog.Setup(seclogtest.MockSecurityLogger(seclogBuf))
+	defer seclog.Setup(seclog.NewNopLogger())
+
+	d := s.newTestDaemon(c)
+	d.Version = "2.78"
+	makeDaemonListeners(c, d)
+	s.markSeeded(d)
+	c.Assert(d.Start(context.Background()), check.IsNil)
+
+	// A tracked goroutine returning this error is what tomb.Wait reports.
+	// It is not a deadline and not net.ErrClosed, so Stop logs and returns it.
+	stopErr := errors.New("cannot stop snapd")
+	d.tomb.Go(func() error {
+		return stopErr
+	})
+	for i := 0; i < 1000 && d.tomb.Err() != stopErr; i++ {
+		time.Sleep(time.Millisecond)
+	}
+	c.Assert(d.tomb.Err(), check.Equals, stopErr)
+
+	err := d.Stop(nil)
+	c.Check(err, check.Equals, stopErr)
+	c.Check(seclogBuf.String(), testutil.Contains, "sys_restart_snapd")
+	c.Check(seclogBuf.String(), testutil.Contains, "Snapd restart with reason "+seclog.SnapdRestartStopFailed)
+	c.Check(seclogBuf.String(), testutil.Contains, `[snapd_version="2.78"]`)
+	c.Check(seclogBuf.String(), testutil.Contains, `[reason="`+seclog.SnapdRestartStopFailed+`"]`)
+	c.Check(seclogBuf.String(), check.Not(testutil.Contains), "sys_standby_snapd")
+}
+
+func (s *daemonSuite) TestStopTombWaitPreseedDoesNotLogRestart(c *check.C) {
+	restore := snapdenv.MockPreseeding(true)
+	defer restore()
+
+	seclogBuf := &bytes.Buffer{}
+	seclog.Setup(seclogtest.MockSecurityLogger(seclogBuf))
+	defer seclog.Setup(seclog.NewNopLogger())
+
+	d := s.newTestDaemon(c)
+	d.Version = "2.78"
+	makeDaemonListeners(c, d)
+	s.markSeeded(d)
+	c.Assert(d.Start(context.Background()), check.IsNil)
+
+	// A tracked goroutine returning this error is what tomb.Wait reports.
+	// Preseed stops on the build host, so Stop returns it without a restart event.
+	stopErr := errors.New("cannot stop snapd")
+	d.tomb.Go(func() error {
+		return stopErr
+	})
+	for i := 0; i < 1000 && d.tomb.Err() != stopErr; i++ {
+		time.Sleep(time.Millisecond)
+	}
+	c.Assert(d.tomb.Err(), check.Equals, stopErr)
+
+	err := d.Stop(nil)
+	c.Check(err, check.Equals, stopErr)
+	c.Check(seclogBuf.String(), check.Not(testutil.Contains), "sys_restart_snapd")
+	c.Check(seclogBuf.String(), check.Not(testutil.Contains), "sys_standby_snapd")
 }
 
 func (s *daemonSuite) TestConnTrackerCanShutdown(c *check.C) {

seclog/eventdata.go

@@ -326,6 +326,14 @@ const (
 	RemoveReasonEnsureExpired SystemUserRemoveReason = "ensure-remove-expired-user"
 )
 
+// Snapd restart reasons that Stop chooses after the fact.
+// They are not restart.RestartReason values and are not passed to
+// restart.Request.
+const (
+	SnapdRestartStopFailed  string = "snapd-stop-failed"
+	SnapdRestartIdleAborted string = "snapd-idle-aborted"
+)
+
 // AssertionRef identifies an assertion by type and primary key. It mirrors
 // asserts.Ref but uses plain strings so the audit payload stays self-contained.
 type AssertionRef struct {

seclog/seclog.go

@@ -27,7 +27,6 @@ import (
 	"syscall"
 
 	"github.com/snapcore/snapd/logger"
-	"github.com/snapcore/snapd/overlord/restart"
 )
 
 // Level is the importance or severity of a log event.
@@ -132,49 +131,49 @@ func LogLoggerDisabled() {
 	)
 }
 
-// LogSystemRestartSnapd logs a controlled snapd daemon restart using the
-// global security logger. snapdVersion is the version of the exiting snapd
-// process. reason is a [restart.RestartReason].
-func LogSystemRestartSnapd(snapdVersion string, reason restart.RestartReason) {
+// LogSystemRestartSnapd logs a snapd daemon restart using the global
+// security logger. snapdVersion is the version of the exiting snapd
+// process. reason is the sys_restart_snapd reason attribute. An empty
+// reason is recorded as "<unknown>".
+func LogSystemRestartSnapd(snapdVersion, reason string) {
 	lock.Lock()
 	defer lock.Unlock()
 
 	if snapdVersion == "" {
 		snapdVersion = unknown
 	}
-	reasonStr := string(reason)
-	if reasonStr == "" {
-		reasonStr = unknown
+	if reason == "" {
+		reason = unknown
 	}
 
 	globalLogger.LogEvent(
 		Event{Category: "SYS", Name: "sys_restart_snapd", Level: LevelInfo},
-		fmt.Sprintf("Snapd restart with reason %s", reasonStr),
+		fmt.Sprintf("Snapd restart with reason %s", reason),
 		Attr{Key: "snapd_version", Value: snapdVersion},
-		Attr{Key: "reason", Value: reasonStr},
+		Attr{Key: "reason", Value: reason},
 	)
 }
 
 // LogSystemStandbySnapd logs a completed socket-activation standby using
 // the global security logger. snapdVersion is the version of the exiting
-// snapd process. reason is a [restart.RestartReason].
-func LogSystemStandbySnapd(snapdVersion string, reason restart.RestartReason) {
+// snapd process. reason is the sys_standby_snapd reason attribute. An
+// empty reason is recorded as "<unknown>".
+func LogSystemStandbySnapd(snapdVersion, reason string) {
 	lock.Lock()
 	defer lock.Unlock()
 
 	if snapdVersion == "" {
 		snapdVersion = unknown
 	}
-	reasonStr := string(reason)
-	if reasonStr == "" {
-		reasonStr = unknown
+	if reason == "" {
+		reason = unknown
 	}
 
 	globalLogger.LogEvent(
 		Event{Category: "SYS", Name: "sys_standby_snapd", Level: LevelInfo},
-		fmt.Sprintf("Snapd standby with reason %s", reasonStr),
+		fmt.Sprintf("Snapd standby with reason %s", reason),
 		Attr{Key: "snapd_version", Value: snapdVersion},
-		Attr{Key: "reason", Value: reasonStr},
+		Attr{Key: "reason", Value: reason},
 	)
 }
 

seclog/seclog_test.go

@@ -209,7 +209,7 @@ func (s *SecLogSuite) TestLogLoggerDisabledNopSkipsNoticef(c *C) {
 }
 
 func (s *SecLogSuite) TestLogSystemRestartSnapd(c *C) {
-	seclog.LogSystemRestartSnapd("2.78", restart.RestartSnapdUpdate)
+	seclog.LogSystemRestartSnapd("2.78", string(restart.RestartSnapdUpdate))
 
 	c.Check(s.buf.String(), testutil.Contains, "sys_restart_snapd")
 	c.Check(s.buf.String(), testutil.Contains, "Snapd restart with reason snapd-update")
@@ -218,7 +218,7 @@ func (s *SecLogSuite) TestLogSystemRestartSnapd(c *C) {
 }
 
 func (s *SecLogSuite) TestLogSystemRestartSnapdUndo(c *C) {
-	seclog.LogSystemRestartSnapd("2.78", restart.RestartSnapdUndo)
+	seclog.LogSystemRestartSnapd("2.78", string(restart.RestartSnapdUndo))
 
 	c.Check(s.buf.String(), testutil.Contains, "sys_restart_snapd")
 	c.Check(s.buf.String(), testutil.Contains, "Snapd restart with reason snapd-undo")
@@ -235,8 +235,26 @@ func (s *SecLogSuite) TestLogSystemRestartSnapdUnknownReason(c *C) {
 	c.Check(s.buf.String(), testutil.Contains, `[reason="<unknown>"]`)
 }
 
+func (s *SecLogSuite) TestLogSystemRestartSnapdStopFailed(c *C) {
+	seclog.LogSystemRestartSnapd("2.78", seclog.SnapdRestartStopFailed)
+
+	c.Check(s.buf.String(), testutil.Contains, "sys_restart_snapd")
+	c.Check(s.buf.String(), testutil.Contains, "Snapd restart with reason snapd-stop-failed")
+	c.Check(s.buf.String(), testutil.Contains, `[snapd_version="2.78"]`)
+	c.Check(s.buf.String(), testutil.Contains, `[reason="snapd-stop-failed"]`)
+}
+
+func (s *SecLogSuite) TestLogSystemRestartSnapdIdleAborted(c *C) {
+	seclog.LogSystemRestartSnapd("2.78", seclog.SnapdRestartIdleAborted)
+
+	c.Check(s.buf.String(), testutil.Contains, "sys_restart_snapd")
+	c.Check(s.buf.String(), testutil.Contains, "Snapd restart with reason snapd-idle-aborted")
+	c.Check(s.buf.String(), testutil.Contains, `[snapd_version="2.78"]`)
+	c.Check(s.buf.String(), testutil.Contains, `[reason="snapd-idle-aborted"]`)
+}
+
 func (s *SecLogSuite) TestLogSystemStandbySnapd(c *C) {
-	seclog.LogSystemStandbySnapd("2.78", restart.RestartSnapdIdle)
+	seclog.LogSystemStandbySnapd("2.78", string(restart.RestartSnapdIdle))
 
 	c.Check(s.buf.String(), testutil.Contains, "sys_standby_snapd")
 	c.Check(s.buf.String(), testutil.Contains, "Snapd standby with reason snapd-idle")

tests/main/security-logging/task.yaml

@@ -45,11 +45,17 @@ prepare: |
     systemctl restart snapd.service
 
 restore: |
+    # Restore the unit override before starting snapd. A process
+    # started while SNAPD_STANDBY_WAIT=1s is still installed keeps
+    # that environment; daemon-reload does not update it.
     if [ -f "$OVERRIDES_FILE.bak" ]; then
         mv "$OVERRIDES_FILE.bak" "$OVERRIDES_FILE"
         systemctl daemon-reload
+        systemctl try-restart snapd.service || true
     fi
 
+    systemctl start snapd.socket snapd.service || true
+
     if [ -f audit-socket-was-inactive ]; then
         systemctl stop systemd-journald-audit.socket
         systemctl restart systemd-journald.service