chore: log the OS signal prior to exiting in agent (#21941)

Adds additional logs for determining what signal the agent receives
prior to shut down. Also helps distinguish whether the signal originated
at the agent or reaper.

agent/reaper/reaper.go

@@ -4,6 +4,8 @@ import (
 	"os"
 
 	"github.com/hashicorp/go-reap"
+
+	"cdr.dev/slog/v3"
 )
 
 type Option func(o *options)
@@ -34,8 +36,15 @@ func WithCatchSignals(sigs ...os.Signal) Option {
 	}
 }
 
+func WithLogger(logger slog.Logger) Option {
+	return func(o *options) {
+		o.Logger = logger
+	}
+}
+
 type options struct {
 	ExecArgs     []string
 	PIDs         reap.PidCh
 	CatchSignals []os.Signal
+	Logger       slog.Logger
 }

agent/reaper/reaper_unix.go

@@ -3,12 +3,15 @@
 package reaper
 
 import (
+	"context"
 	"os"
 	"os/signal"
 	"syscall"
 
 	"github.com/hashicorp/go-reap"
 	"golang.org/x/xerrors"
+
+	"cdr.dev/slog/v3"
 )
 
 // IsInitProcess returns true if the current process's PID is 1.
@@ -16,7 +19,7 @@ func IsInitProcess() bool {
 	return os.Getpid() == 1
 }
 
-func catchSignals(pid int, sigs []os.Signal) {
+func catchSignals(logger slog.Logger, pid int, sigs []os.Signal) {
 	if len(sigs) == 0 {
 		return
 	}
@@ -25,10 +28,19 @@ func catchSignals(pid int, sigs []os.Signal) {
 	signal.Notify(sc, sigs...)
 	defer signal.Stop(sc)
 
+	logger.Info(context.Background(), "reaper catching signals",
+		slog.F("signals", sigs),
+		slog.F("child_pid", pid),
+	)
+
 	for {
 		s := <-sc
 		sig, ok := s.(syscall.Signal)
 		if ok {
+			logger.Info(context.Background(), "reaper caught signal, killing child process",
+				slog.F("signal", sig.String()),
+				slog.F("child_pid", pid),
+			)
 			_ = syscall.Kill(pid, sig)
 		}
 	}
@@ -78,7 +90,7 @@ func ForkReap(opt ...Option) (int, error) {
 		return 1, xerrors.Errorf("fork exec: %w", err)
 	}
 
-	go catchSignals(pid, opts.CatchSignals)
+	go catchSignals(opts.Logger, pid, opts.CatchSignals)
 
 	var wstatus syscall.WaitStatus
 	_, err = syscall.Wait4(pid, &wstatus, 0, nil)

cli/agent.go

@@ -9,6 +9,7 @@ import (
 	"net/http/pprof"
 	"net/url"
 	"os"
+	"os/signal"
 	"path/filepath"
 	"runtime"
 	"slices"
@@ -130,6 +131,7 @@ func workspaceAgent() *serpent.Command {
 
 				sinks = append(sinks, sloghuman.Sink(logWriter))
 				logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug)
+				logger = logger.Named("reaper")
 
 				logger.Info(ctx, "spawning reaper process")
 				// Do not start a reaper on the child process. It's important
@@ -139,31 +141,19 @@ func workspaceAgent() *serpent.Command {
 				exitCode, err := reaper.ForkReap(
 					reaper.WithExecArgs(args...),
 					reaper.WithCatchSignals(StopSignals...),
+					reaper.WithLogger(logger),
 				)
 				if err != nil {
 					logger.Error(ctx, "agent process reaper unable to fork", slog.Error(err))
 					return xerrors.Errorf("fork reap: %w", err)
 				}
 
-				logger.Info(ctx, "reaper child process exited", slog.F("exit_code", exitCode))
+				logger.Info(ctx, "child process exited, propagating exit code",
+					slog.F("exit_code", exitCode),
+				)
 				return ExitError(exitCode, nil)
 			}
 
-			// Handle interrupt signals to allow for graceful shutdown,
-			// note that calling stopNotify disables the signal handler
-			// and the next interrupt will terminate the program (you
-			// probably want cancel instead).
-			//
-			// Note that we don't want to handle these signals in the
-			// process that runs as PID 1, that's why we do this after
-			// the reaper forked.
-			ctx, stopNotify := inv.SignalNotifyContext(ctx, StopSignals...)
-			defer stopNotify()
-
-			// DumpHandler does signal handling, so we call it after the
-			// reaper.
-			go DumpHandler(ctx, "agent")
-
 			logWriter := &clilog.LumberjackWriteCloseFixer{Writer: &lumberjack.Logger{
 				Filename: filepath.Join(logDir, "coder-agent.log"),
 				MaxSize:  5, // MB
@@ -176,6 +166,21 @@ func workspaceAgent() *serpent.Command {
 			sinks = append(sinks, sloghuman.Sink(logWriter))
 			logger := inv.Logger.AppendSinks(sinks...).Leveled(slog.LevelDebug)
 
+			// Handle interrupt signals to allow for graceful shutdown,
+			// note that calling stopNotify disables the signal handler
+			// and the next interrupt will terminate the program (you
+			// probably want cancel instead).
+			//
+			// Note that we also handle these signals in the
+			// process that runs as PID 1, mainly to forward it to the agent child
+			// so that it can shutdown gracefully.
+			ctx, stopNotify := logSignalNotifyContext(ctx, logger, StopSignals...)
+			defer stopNotify()
+
+			// DumpHandler does signal handling, so we call it after the
+			// reaper.
+			go DumpHandler(ctx, "agent")
+
 			version := buildinfo.Version()
 			logger.Info(ctx, "agent is starting now",
 				slog.F("url", agentAuth.agentURL),
@@ -565,3 +570,26 @@ func urlPort(u string) (int, error) {
 	}
 	return -1, xerrors.Errorf("invalid port: %s", u)
 }
+
+// logSignalNotifyContext is like signal.NotifyContext but logs the received
+// signal before canceling the context.
+func logSignalNotifyContext(parent context.Context, logger slog.Logger, signals ...os.Signal) (context.Context, context.CancelFunc) {
+	ctx, cancel := context.WithCancelCause(parent)
+	c := make(chan os.Signal, 1)
+	signal.Notify(c, signals...)
+
+	go func() {
+		select {
+		case sig := <-c:
+			logger.Info(ctx, "agent received signal", slog.F("signal", sig.String()))
+			cancel(xerrors.Errorf("signal: %s", sig.String()))
+		case <-ctx.Done():
+			logger.Info(ctx, "ctx canceled, stopping signal handler")
+		}
+	}()
+
+	return ctx, func() {
+		cancel(context.Canceled)
+		signal.Stop(c)
+	}
+}