diff --git a/agent/reaper/reaper.go b/agent/reaper/reaper.go index 94f5190d11..d968937a3a 100644 --- a/agent/reaper/reaper.go +++ b/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 } diff --git a/agent/reaper/reaper_unix.go b/agent/reaper/reaper_unix.go index 255077284c..b095c5a7f9 100644 --- a/agent/reaper/reaper_unix.go +++ b/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) diff --git a/cli/agent.go b/cli/agent.go index 58efeb0c18..1d530b0552 100644 --- a/cli/agent.go +++ b/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) + } +}