From 84c2b143b25222ba7629dc21247b36bde3d1447f Mon Sep 17 00:00:00 2001 From: james pickett Date: Mon, 5 Feb 2024 10:16:02 -0800 Subject: [PATCH] now using slogger in desktop and all its dependencies --- cmd/launcher/desktop.go | 84 +++++++++++++------------ cmd/launcher/desktop_test.go | 9 ++- cmd/launcher/launcher.go | 2 +- ee/desktop/user/client/client_test.go | 5 +- ee/desktop/user/menu/action_flare.go | 8 ++- ee/desktop/user/menu/action_message.go | 24 +++---- ee/desktop/user/menu/action_open_url.go | 10 +-- ee/desktop/user/menu/menu.go | 21 ++++--- ee/desktop/user/notify/notify_darwin.go | 9 ++- ee/desktop/user/server/server.go | 37 +++++++---- ee/desktop/user/server/server_test.go | 8 ++- pkg/rungroup/rungroup.go | 63 ++++++++++++++----- pkg/rungroup/rungroup_test.go | 10 +-- 13 files changed, 182 insertions(+), 108 deletions(-) diff --git a/cmd/launcher/desktop.go b/cmd/launcher/desktop.go index 85147c8032..5eee693498 100644 --- a/cmd/launcher/desktop.go +++ b/cmd/launcher/desktop.go @@ -5,15 +5,15 @@ import ( "flag" "fmt" "io" + "log/slog" "os" "os/signal" "os/user" "runtime" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" - "github.com/kolide/kit/logutil" + // "github.com/go-kit/kit/log" + "github.com/kolide/kit/ulid" "github.com/kolide/launcher/ee/agent" runnerserver "github.com/kolide/launcher/ee/desktop/runner/server" @@ -75,9 +75,15 @@ func runDesktop(args []string) error { return fmt.Errorf("parsing flags: %w", err) } - // set up logging - logger := logutil.NewServerLogger(*fldebug) - logger = log.With(logger, + logLevel := slog.LevelInfo + if *fldebug { + logLevel = slog.LevelDebug + } + + slogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ + AddSource: true, + Level: logLevel, + })).With( "subprocess", "desktop", "session_pid", os.Getpid(), ) @@ -85,51 +91,51 @@ func runDesktop(args []string) error { // Try to get the current user, so we can use the UID for logging. Not a fatal error if we can't, though user, err := user.Current() if err != nil { - level.Debug(logger).Log( - "msg", "error getting current user", + slogger.Log(context.TODO(), slog.LevelDebug, + "error getting current user", "err", err, ) } else { - logger = log.With(logger, - "uid", user.Uid, - ) + slogger = slogger.With("uid", user.Uid) } - level.Info(logger).Log("msg", "starting") + slogger.Log(context.TODO(), slog.LevelInfo, + "starting", + ) if *flUserServerSocketPath == "" { *flUserServerSocketPath = defaultUserServerSocketPath() - level.Info(logger).Log( - "msg", "using default socket path since none was provided", + slogger.Log(context.TODO(), slog.LevelInfo, + "using default socket path since none was provided", "socket_path", *flUserServerSocketPath, ) } - runGroup := rungroup.NewRunGroup(logger) + runGroup := rungroup.NewRunGroup(slogger) // listen for signals runGroup.Add("desktopSignalListener", func() error { - listenSignals(logger) + listenSignals(slogger) return nil }, func(error) {}) // Set up notification sending and listening - notifier := notify.NewDesktopNotifier(logger, *flIconPath) + notifier := notify.NewDesktopNotifier(slogger, *flIconPath) runGroup.Add("desktopNotifier", notifier.Listen, notifier.Interrupt) // monitor parent runGroup.Add("desktopMonitorParentProcess", func() error { - monitorParentProcess(logger, *flRunnerServerUrl, *flRunnerServerAuthToken, 2*time.Second) + monitorParentProcess(slogger, *flRunnerServerUrl, *flRunnerServerAuthToken, 2*time.Second) return nil }, func(error) {}) shutdownChan := make(chan struct{}) - server, err := userserver.New(logger, *flUserServerAuthToken, *flUserServerSocketPath, shutdownChan, notifier) + server, err := userserver.New(slogger, *flUserServerAuthToken, *flUserServerSocketPath, shutdownChan, notifier) if err != nil { return err } - m := menu.New(logger, *flhostname, *flmenupath) + m := menu.New(slogger, *flhostname, *flmenupath) refreshMenu := func() { m.Build() } @@ -140,8 +146,8 @@ func runDesktop(args []string) error { ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() if err := server.Shutdown(ctx); err != nil { - level.Error(logger).Log( - "msg", "shutting down server", + slogger.Log(context.TODO(), slog.LevelError, + "shutting down server", "err", err, ) } @@ -157,7 +163,7 @@ func runDesktop(args []string) error { // notify runner server when menu opened runGroup.Add("desktopMenuOpenedListener", func() error { - notifyRunnerServerMenuOpened(logger, *flRunnerServerUrl, *flRunnerServerAuthToken) + notifyRunnerServerMenuOpened(slogger, *flRunnerServerUrl, *flRunnerServerAuthToken) return nil }, func(err error) {}) @@ -165,8 +171,8 @@ func runDesktop(args []string) error { go func() { // have to run this in a goroutine because menu needs the main thread if err := runGroup.Run(); err != nil { - level.Error(logger).Log( - "msg", "running run group", + slogger.Log(context.TODO(), slog.LevelError, + "running run group", "err", err, ) } @@ -178,20 +184,20 @@ func runDesktop(args []string) error { return nil } -func listenSignals(logger log.Logger) { +func listenSignals(slogger *slog.Logger) { signalsToHandle := []os.Signal{os.Interrupt, os.Kill} signals := make(chan os.Signal, len(signalsToHandle)) signal.Notify(signals, signalsToHandle...) sig := <-signals - level.Debug(logger).Log( - "msg", "received signal", + slogger.Log(context.TODO(), slog.LevelDebug, + "received signal", "signal", sig, ) } -func notifyRunnerServerMenuOpened(logger log.Logger, rootServerUrl, authToken string) { +func notifyRunnerServerMenuOpened(slogger *slog.Logger, rootServerUrl, authToken string) { client := authedclient.New(authToken, 2*time.Second) menuOpendUrl := fmt.Sprintf("%s%s", rootServerUrl, runnerserver.MenuOpenedEndpoint) @@ -200,8 +206,8 @@ func notifyRunnerServerMenuOpened(logger log.Logger, rootServerUrl, authToken st response, err := client.Get(menuOpendUrl) if err != nil { - level.Error(logger).Log( - "msg", "sending menu opened request to root server", + slogger.Log(context.TODO(), slog.LevelError, + "sending menu opened request to root server", "err", err, ) } @@ -213,7 +219,7 @@ func notifyRunnerServerMenuOpened(logger log.Logger, rootServerUrl, authToken st } // monitorParentProcess continuously checks to see if parent is a live and sends on provided channel if it is not -func monitorParentProcess(logger log.Logger, runnerServerUrl, runnerServerAuthToken string, interval time.Duration) { +func monitorParentProcess(slogger *slog.Logger, runnerServerUrl, runnerServerAuthToken string, interval time.Duration) { ticker := time.NewTicker(interval) defer ticker.Stop() @@ -227,8 +233,8 @@ func monitorParentProcess(logger log.Logger, runnerServerUrl, runnerServerAuthTo for ; true; <-ticker.C { // check to to ensure that the ppid is still legit if os.Getppid() < 2 { - level.Debug(logger).Log( - "msg", "ppid is 0 or 1, exiting", + slogger.Log(context.TODO(), slog.LevelDebug, + "ppid is 0 or 1, exiting", ) break } @@ -255,8 +261,8 @@ func monitorParentProcess(logger log.Logger, runnerServerUrl, runnerServerAuthTo // retry if errCount < maxErrCount { - level.Debug(logger).Log( - "msg", "could not connect to parent, will retry", + slogger.Log(context.TODO(), slog.LevelDebug, + "could not connect to parent, will retry", "err", err, "attempts", errCount, "max_attempts", maxErrCount, @@ -265,9 +271,9 @@ func monitorParentProcess(logger log.Logger, runnerServerUrl, runnerServerAuthTo continue } - // errCount => maxErrCount, exit - level.Debug(logger).Log( - "msg", "could not connect to parent, max attempts reached, exiting", + // errCount >= maxErrCount, exit + slogger.Log(context.TODO(), slog.LevelDebug, + "could not connect to parent, max attempts reached, exiting", "err", err, "attempts", errCount, "max_attempts", maxErrCount, diff --git a/cmd/launcher/desktop_test.go b/cmd/launcher/desktop_test.go index 79a8d06c37..4f495e7d62 100644 --- a/cmd/launcher/desktop_test.go +++ b/cmd/launcher/desktop_test.go @@ -3,11 +3,11 @@ package main import ( "context" "io" + "log/slog" "net/http" "testing" "time" - "github.com/go-kit/kit/log" runnerserver "github.com/kolide/launcher/ee/desktop/runner/server" "github.com/kolide/launcher/pkg/log/multislogger" "github.com/kolide/launcher/pkg/threadsafebuffer" @@ -24,8 +24,13 @@ func Test_desktopMonitorParentProcess(t *testing.T) { //nolint:paralleltest monitorInterval := 250 * time.Millisecond var logBytes threadsafebuffer.ThreadSafeBuffer + slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{ + AddSource: true, + Level: slog.LevelDebug, + })) + go func() { - monitorParentProcess(log.NewLogfmtLogger(&logBytes), runnerServer.Url(), token, monitorInterval) + monitorParentProcess(slogger, runnerServer.Url(), token, monitorInterval) }() time.Sleep(monitorInterval * 2) diff --git a/cmd/launcher/launcher.go b/cmd/launcher/launcher.go index 235075b924..cec7157c96 100644 --- a/cmd/launcher/launcher.go +++ b/cmd/launcher/launcher.go @@ -198,7 +198,7 @@ func runLauncher(ctx context.Context, cancel func(), multiSlogger, systemMultiSl } // create a rungroup for all the actors we create to allow for easy start/stop - runGroup := rungroup.NewRunGroup(logger) + runGroup := rungroup.NewRunGroup(slogger) // Need to set up the log shipper so that we can get the logger early // and pass it to the various systems. diff --git a/ee/desktop/user/client/client_test.go b/ee/desktop/user/client/client_test.go index fb3efcb970..76f663aec4 100644 --- a/ee/desktop/user/client/client_test.go +++ b/ee/desktop/user/client/client_test.go @@ -9,9 +9,8 @@ import ( "strings" "testing" - "github.com/go-kit/kit/log" - "github.com/kolide/launcher/ee/desktop/user/server" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -43,7 +42,7 @@ func TestClient_GetAndShutdown(t *testing.T) { socketPath := testSocketPath(t) shutdownChan := make(chan struct{}) - server, err := server.New(log.NewNopLogger(), validAuthToken, socketPath, shutdownChan, nil) + server, err := server.New(multislogger.New().Logger, validAuthToken, socketPath, shutdownChan, nil) require.NoError(t, err) go func() { diff --git a/ee/desktop/user/menu/action_flare.go b/ee/desktop/user/menu/action_flare.go index 4bebe9170c..b9fcb36926 100644 --- a/ee/desktop/user/menu/action_flare.go +++ b/ee/desktop/user/menu/action_flare.go @@ -1,7 +1,8 @@ package menu import ( - "github.com/go-kit/kit/log/level" + "context" + "log/slog" ) // actionFlare performs the launcher flare action. This will make more sense once flare is uploading @@ -11,7 +12,10 @@ type actionFlare struct { func (a actionFlare) Perform(m *menu) { if err := runFlare(); err != nil { - level.Error(m.logger).Log("msg", "error creating flare", "err", err) + m.slogger.Log(context.TODO(), slog.LevelError, + "error creating flare", + "err", err, + ) } } diff --git a/ee/desktop/user/menu/action_message.go b/ee/desktop/user/menu/action_message.go index 080a2e8da8..1cbae3a3bf 100644 --- a/ee/desktop/user/menu/action_message.go +++ b/ee/desktop/user/menu/action_message.go @@ -2,13 +2,14 @@ package menu import ( "bytes" + "context" "encoding/json" "fmt" + "log/slog" "net/http" "os" "time" - "github.com/go-kit/kit/log/level" "github.com/kolide/launcher/ee/desktop/runner/server" "github.com/kolide/launcher/pkg/authedclient" ) @@ -22,16 +23,16 @@ type actionMessage struct { func (a actionMessage) Perform(m *menu) { runnerServerUrl := os.Getenv("RUNNER_SERVER_URL") if runnerServerUrl == "" { - level.Error(m.logger).Log( - "msg", "runner server url not set", + m.slogger.Log(context.TODO(), slog.LevelError, + "runner server url not set", ) return } runnerServerAuthToken := os.Getenv("RUNNER_SERVER_AUTH_TOKEN") if runnerServerAuthToken == "" { - level.Error(m.logger).Log( - "msg", "runner server auth token not set", + m.slogger.Log(context.TODO(), slog.LevelError, + "runner server auth token not set", ) return } @@ -41,17 +42,18 @@ func (a actionMessage) Perform(m *menu) { jsonBody, err := json.Marshal(a) if err != nil { - level.Error(m.logger).Log( - "msg", "failed to marshal message body", + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to marshal message body", "err", err, ) + return } response, err := client.Post(runnerMessageUrl, "application/json", bytes.NewReader(jsonBody)) if err != nil { - level.Error(m.logger).Log( - "msg", "failed to perform message action", + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to perform message action", "method", a.Method, "params", a.Params, "err", err, @@ -65,8 +67,8 @@ func (a actionMessage) Perform(m *menu) { } if response.StatusCode != http.StatusOK { - level.Error(m.logger).Log( - "msg", "failed to perform message action", + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to perform message action", "method", a.Method, "params", a.Params, "status_code", response.StatusCode, diff --git a/ee/desktop/user/menu/action_open_url.go b/ee/desktop/user/menu/action_open_url.go index 169576f9e0..5ef1539828 100644 --- a/ee/desktop/user/menu/action_open_url.go +++ b/ee/desktop/user/menu/action_open_url.go @@ -1,7 +1,8 @@ package menu import ( - "github.com/go-kit/kit/log/level" + "context" + "log/slog" ) // Performs the OpenURL action @@ -11,9 +12,10 @@ type actionOpenURL struct { func (a actionOpenURL) Perform(m *menu) { if err := open(a.URL); err != nil { - level.Error(m.logger).Log( - "msg", "failed to perform action", + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to perform action", "URL", a.URL, - "err", err) + "err", err, + ) } } diff --git a/ee/desktop/user/menu/menu.go b/ee/desktop/user/menu/menu.go index 6d6763233f..4cfe76d57d 100644 --- a/ee/desktop/user/menu/menu.go +++ b/ee/desktop/user/menu/menu.go @@ -1,13 +1,13 @@ package menu import ( + "context" _ "embed" "encoding/json" "fmt" + "log/slog" "os" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "github.com/kolide/kit/version" ) @@ -57,14 +57,14 @@ type menuBuilder interface { // menu handles common functionality like retrieving menu data, and allows menu builders to provide their implementations type menu struct { - logger log.Logger + slogger *slog.Logger hostname string filePath string } -func New(logger log.Logger, hostname, filePath string) *menu { +func New(slogger *slog.Logger, hostname, filePath string) *menu { m := &menu{ - logger: logger, + slogger: slogger.With("component", "desktop_menu"), hostname: hostname, filePath: filePath, } @@ -85,12 +85,19 @@ func (m *menu) getMenuData() *MenuData { menuFileBytes, err := os.ReadFile(m.filePath) if err != nil { - level.Error(m.logger).Log("msg", "failed to read menu file", "path", m.filePath, "err", err) + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to read menu file", + "path", m.filePath, + "err", err, + ) return &menu } if err := json.Unmarshal(menuFileBytes, &menu); err != nil { - level.Error(m.logger).Log("msg", "failed to unmarshal menu json", "err", err) + m.slogger.Log(context.TODO(), slog.LevelError, + "failed to unmarshal menu json", + "err", err, + ) return &menu } diff --git a/ee/desktop/user/notify/notify_darwin.go b/ee/desktop/user/notify/notify_darwin.go index ff9fa780ae..ee8e92242c 100644 --- a/ee/desktop/user/notify/notify_darwin.go +++ b/ee/desktop/user/notify/notify_darwin.go @@ -17,21 +17,20 @@ import "C" import ( "errors" "fmt" + "log/slog" "os" "strings" "unsafe" - - "github.com/go-kit/kit/log" ) type macNotifier struct { - logger log.Logger + slogger *slog.Logger interrupt chan struct{} } -func NewDesktopNotifier(logger log.Logger, _ string) *macNotifier { +func NewDesktopNotifier(slogger *slog.Logger, _ string) *macNotifier { return &macNotifier{ - logger: log.With(logger, "component", "desktop_notifier"), + slogger: slogger.With("component", "desktop_notifier"), interrupt: make(chan struct{}), } } diff --git a/ee/desktop/user/server/server.go b/ee/desktop/user/server/server.go index 1b006441c3..87bd166365 100644 --- a/ee/desktop/user/server/server.go +++ b/ee/desktop/user/server/server.go @@ -7,6 +7,7 @@ import ( "context" "encoding/json" "io" + "log/slog" "net" "net/http" "os" @@ -14,8 +15,6 @@ import ( "strings" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "github.com/kolide/launcher/ee/desktop/user/notify" "github.com/kolide/launcher/pkg/backoff" ) @@ -27,7 +26,7 @@ type notificationSender interface { // UserServer provides IPC for the root desktop runner to communicate with the user desktop processes. // It allows the runner process to send notficaitons and commands to the desktop processes. type UserServer struct { - logger log.Logger + slogger *slog.Logger server *http.Server listener net.Listener shutdownChan chan<- struct{} @@ -37,11 +36,11 @@ type UserServer struct { refreshListeners []func() } -func New(logger log.Logger, authToken string, socketPath string, shutdownChan chan<- struct{}, notifier notificationSender) (*UserServer, error) { +func New(slogger *slog.Logger, authToken string, socketPath string, shutdownChan chan<- struct{}, notifier notificationSender) (*UserServer, error) { userServer := &UserServer{ shutdownChan: shutdownChan, authToken: authToken, - logger: log.With(logger, "component", "desktop_server"), + slogger: slogger.With("component", "desktop_server"), socketPath: socketPath, notifier: notifier, } @@ -74,7 +73,10 @@ func New(logger log.Logger, authToken string, socketPath string, shutdownChan ch userServer.server.RegisterOnShutdown(func() { // remove socket on shutdown if err := userServer.removeSocket(); err != nil { - level.Error(logger).Log("msg", "removing socket on shutdown", "err", err) + slogger.Log(context.TODO(), slog.LevelError, + "removing socket on shutdown", + "err", err, + ) } }) @@ -119,7 +121,10 @@ func (s *UserServer) notificationHandler(w http.ResponseWriter, req *http.Reques w.Header().Set("Content-Type", "application/json") b, err := io.ReadAll(req.Body) if err != nil { - level.Error(s.logger).Log("msg", "could not read body of notification request", "err", err) + s.slogger.Log(context.TODO(), slog.LevelError, + "could not read body of notification request", + "err", err, + ) w.WriteHeader(http.StatusBadRequest) return } @@ -127,13 +132,19 @@ func (s *UserServer) notificationHandler(w http.ResponseWriter, req *http.Reques var notificationToSend notify.Notification if err := json.Unmarshal(b, ¬ificationToSend); err != nil { - level.Error(s.logger).Log("msg", "could not decode notification request", "err", err) + s.slogger.Log(context.TODO(), slog.LevelError, + "could not decode notification request", + "err", err, + ) w.WriteHeader(http.StatusBadRequest) return } if err := s.notifier.SendNotification(notificationToSend); err != nil { - level.Error(s.logger).Log("msg", "could not send notification", "err", err) + s.slogger.Log(context.TODO(), slog.LevelError, + "could not send notification", + "err", err, + ) w.WriteHeader(http.StatusInternalServerError) return } @@ -165,13 +176,17 @@ func (s *UserServer) authMiddleware(next http.Handler) http.Handler { authHeader := strings.Split(r.Header.Get("Authorization"), "Bearer ") if len(authHeader) != 2 { - level.Debug(s.logger).Log("msg", "malformed authorization header") + s.slogger.Log(context.TODO(), slog.LevelDebug, + "malformed authorization header", + ) w.WriteHeader(http.StatusUnauthorized) return } if authHeader[1] != s.authToken { - level.Debug(s.logger).Log("msg", "invalid authorization token") + s.slogger.Log(context.TODO(), slog.LevelDebug, + "invalid authorization token", + ) w.WriteHeader(http.StatusUnauthorized) return } diff --git a/ee/desktop/user/server/server_test.go b/ee/desktop/user/server/server_test.go index 3c6980c29f..aceef91934 100644 --- a/ee/desktop/user/server/server_test.go +++ b/ee/desktop/user/server/server_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "fmt" + "log/slog" "net/http" "net/http/httptest" "os" @@ -12,7 +13,6 @@ import ( "strings" "testing" - "github.com/go-kit/kit/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -116,7 +116,11 @@ func testHandler() http.Handler { func testServer(t *testing.T, authHeader, socketPath string, logBytes *bytes.Buffer) (*UserServer, chan struct{}) { shutdownChan := make(chan struct{}) - server, err := New(log.NewLogfmtLogger(logBytes), authHeader, socketPath, shutdownChan, nil) + slogger := slog.New(slog.NewTextHandler(logBytes, &slog.HandlerOptions{ + AddSource: true, + Level: slog.LevelDebug, + })) + server, err := New(slogger, authHeader, socketPath, shutdownChan, nil) require.NoError(t, err) return server, shutdownChan } diff --git a/pkg/rungroup/rungroup.go b/pkg/rungroup/rungroup.go index b1cd065a26..20a9f66574 100644 --- a/pkg/rungroup/rungroup.go +++ b/pkg/rungroup/rungroup.go @@ -8,17 +8,16 @@ package rungroup import ( "context" "fmt" + "log/slog" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "golang.org/x/sync/semaphore" ) type ( Group struct { - logger log.Logger - actors []rungroupActor + slogger *slog.Logger + actors []rungroupActor } rungroupActor struct { @@ -38,10 +37,10 @@ const ( executeReturnTimeout = 5 * time.Second // After interrupted, how long for all actors to exit their `execute` functions ) -func NewRunGroup(logger log.Logger) *Group { +func NewRunGroup(slogger *slog.Logger) *Group { return &Group{ - logger: log.With(logger, "component", "run_group"), - actors: make([]rungroupActor, 0), + slogger: slogger.With("component", "run_group"), + actors: make([]rungroupActor, 0), } } @@ -55,11 +54,18 @@ func (g *Group) Run() error { } // Run each actor. - level.Debug(g.logger).Log("msg", "starting all actors", "actor_count", len(g.actors)) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "starting all actors", + "actor_count", len(g.actors), + ) + errors := make(chan actorError, len(g.actors)) for _, a := range g.actors { go func(a rungroupActor) { - level.Debug(g.logger).Log("msg", "starting actor", "actor", a.name) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "starting actor", + "actor", a.name, + ) err := a.execute() errors <- actorError{ errorSourceName: a.name, @@ -70,8 +76,17 @@ func (g *Group) Run() error { // Wait for the first actor to stop. initialActorErr := <-errors - level.Debug(g.logger).Log("msg", "received interrupt error from first actor -- shutting down other actors", "err", initialActorErr) - defer level.Debug(g.logger).Log("msg", "done shutting down actors", "actor_count", len(g.actors), "initial_err", initialActorErr) + + g.slogger.Log(context.TODO(), slog.LevelDebug, + "received interrupt error from first actor -- shutting down other actors", + "err", initialActorErr, + ) + + defer g.slogger.Log(context.TODO(), slog.LevelDebug, + "done shutting down actors", + "actor_count", len(g.actors), + "initial_err", initialActorErr, + ) // Signal all actors to stop. numActors := int64(len(g.actors)) @@ -80,9 +95,15 @@ func (g *Group) Run() error { interruptWait.Acquire(context.Background(), 1) go func(a rungroupActor) { defer interruptWait.Release(1) - level.Debug(g.logger).Log("msg", "interrupting actor", "actor", a.name) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "interrupting actor", + "actor", a.name, + ) a.interrupt(initialActorErr.err) - level.Debug(g.logger).Log("msg", "interrupt complete", "actor", a.name) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "interrupt complete", + "actor", a.name, + ) }(a) } @@ -91,7 +112,10 @@ func (g *Group) Run() error { // Wait for interrupts to complete, but only until we hit our interruptCtx timeout if err := interruptWait.Acquire(interruptCtx, numActors); err != nil { - level.Debug(g.logger).Log("msg", "timeout waiting for interrupts to complete, proceeding with shutdown", "err", err) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "timeout waiting for interrupts to complete, proceeding with shutdown", + "err", err, + ) } // Wait for all other actors to stop, but only until we hit our executeReturnTimeout @@ -100,12 +124,19 @@ func (g *Group) Run() error { for i := 1; i < cap(errors); i++ { select { case <-timeoutTimer.C: - level.Debug(g.logger).Log("msg", "rungroup shutdown deadline exceeded, not waiting for any more actors to return") + g.slogger.Log(context.TODO(), slog.LevelDebug, + "rungroup shutdown deadline exceeded, not waiting for any more actors to return", + ) // Return the original error so we can proceed with shutdown return initialActorErr.err case e := <-errors: - level.Debug(g.logger).Log("msg", "execute returned", "actor", e.errorSourceName, "index", i) + g.slogger.Log(context.TODO(), slog.LevelDebug, + "received error from actor", + "actor", e.errorSourceName, + "err", e.err, + "index", i, + ) } } diff --git a/pkg/rungroup/rungroup_test.go b/pkg/rungroup/rungroup_test.go index ae7b459350..d680526f76 100644 --- a/pkg/rungroup/rungroup_test.go +++ b/pkg/rungroup/rungroup_test.go @@ -5,21 +5,21 @@ import ( "testing" "time" - "github.com/go-kit/kit/log" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/stretchr/testify/require" ) func TestRun_NoActors(t *testing.T) { t.Parallel() - testRunGroup := NewRunGroup(log.NewNopLogger()) + testRunGroup := NewRunGroup(multislogger.New().Logger) require.NoError(t, testRunGroup.Run()) } func TestRun_MultipleActors(t *testing.T) { t.Parallel() - testRunGroup := NewRunGroup(log.NewNopLogger()) + testRunGroup := NewRunGroup(multislogger.New().Logger) groupReceivedInterrupts := make(chan struct{}, 3) @@ -90,7 +90,7 @@ func TestRun_MultipleActors(t *testing.T) { func TestRun_MultipleActors_InterruptTimeout(t *testing.T) { t.Parallel() - testRunGroup := NewRunGroup(log.NewNopLogger()) + testRunGroup := NewRunGroup(multislogger.New().Logger) groupReceivedInterrupts := make(chan struct{}, 3) @@ -163,7 +163,7 @@ func TestRun_MultipleActors_InterruptTimeout(t *testing.T) { func TestRun_MultipleActors_ExecuteReturnTimeout(t *testing.T) { t.Parallel() - testRunGroup := NewRunGroup(log.NewNopLogger()) + testRunGroup := NewRunGroup(multislogger.New().Logger) groupReceivedInterrupts := make(chan struct{}, 3) // Keep track of when `execute`s return so we give testRunGroup.Run enough time to do its thing