diff --git a/cmd/launcher/interactive.go b/cmd/launcher/interactive.go index 99f3d4869..1ad669c41 100644 --- a/cmd/launcher/interactive.go +++ b/cmd/launcher/interactive.go @@ -9,7 +9,6 @@ import ( "os" "strings" - "github.com/kolide/kit/logutil" "github.com/kolide/launcher/cmd/launcher/internal" "github.com/kolide/launcher/ee/agent" "github.com/kolide/launcher/ee/tuf" @@ -34,8 +33,6 @@ func runInteractive(args []string) error { return err } - logger := logutil.NewServerLogger(*flDebug) - slogLevel := slog.LevelInfo if *flDebug { slogLevel = slog.LevelDebug @@ -47,7 +44,7 @@ func runInteractive(args []string) error { osquerydPath := *flOsquerydPath if osquerydPath == "" { - latestOsquerydBinary, err := tuf.CheckOutLatestWithoutConfig("osqueryd", logger) + latestOsquerydBinary, err := tuf.CheckOutLatestWithoutConfig("osqueryd", slogger) if err != nil { osquerydPath = launcher.FindOsquery() if osquerydPath == "" { diff --git a/cmd/launcher/launcher.go b/cmd/launcher/launcher.go index 90952c30f..77541cfa7 100644 --- a/cmd/launcher/launcher.go +++ b/cmd/launcher/launcher.go @@ -328,7 +328,7 @@ func runLauncher(ctx context.Context, cancel func(), multiSlogger, systemMultiSl osqueryruntime.WithOsquerydBinary(k.OsquerydPath()), osqueryruntime.WithRootDirectory(k.RootDirectory()), osqueryruntime.WithOsqueryExtensionPlugins(table.LauncherTables(k)...), - osqueryruntime.WithLogger(logger), + osqueryruntime.WithSlogger(k.Slogger().With("component", "osquery_instance")), osqueryruntime.WithOsqueryVerbose(k.OsqueryVerbose()), osqueryruntime.WithOsqueryFlags(k.OsqueryFlags()), osqueryruntime.WithStdout(kolidelog.NewOsqueryLogAdapter( diff --git a/cmd/launcher/main.go b/cmd/launcher/main.go index d0e9ce911..08e350ae2 100644 --- a/cmd/launcher/main.go +++ b/cmd/launcher/main.go @@ -11,7 +11,6 @@ import ( "text/tabwriter" "time" - "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" "github.com/kolide/kit/env" "github.com/kolide/kit/logutil" @@ -44,13 +43,18 @@ func main() { ctx = ctxlog.NewContext(ctx, logger) + // set up system slogger to write to os logs + systemSlogger := multislogger.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{ + Level: slog.LevelInfo, + })) + // If there's a newer version of launcher on disk, use it. // Allow a caller to set `LAUNCHER_SKIP_UPDATES` as a way to // skip exec'ing an update. This helps prevent launcher from // fork-bombing itself. This is an ENV, because there's no // good way to pass it through the flags. if !env.Bool("LAUNCHER_SKIP_UPDATES", false) { - runNewerLauncherIfAvailable(ctx, logger) + runNewerLauncherIfAvailable(ctx, systemSlogger.Logger) } // if the launcher is being ran with a positional argument, @@ -71,11 +75,6 @@ func main() { // recreate the logger with the appropriate level. logger = logutil.NewServerLogger(opts.Debug) - // set up system slogger to write to os logs - systemSlogger := multislogger.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{ - Level: slog.LevelInfo, - })) - // set up slogger for internal launcher logging slogger := multislogger.New() @@ -118,7 +117,7 @@ func main() { if err := runLauncher(ctx, cancel, slogger, systemSlogger, opts); err != nil { if tuf.IsLauncherReloadNeededErr(err) { level.Debug(logger).Log("msg", "runLauncher exited to run newer version of launcher", "err", err.Error()) - runNewerLauncherIfAvailable(ctx, logger) + runNewerLauncherIfAvailable(ctx, slogger.Logger) } else { level.Debug(logger).Log("msg", "run launcher", "stack", fmt.Sprintf("%+v", err)) logutil.Fatal(logger, err, "run launcher") @@ -167,11 +166,11 @@ func runSubcommands() error { // runNewerLauncherIfAvailable checks the autoupdate library for a newer version // of launcher than the currently-running one. If found, it will exec that version. -func runNewerLauncherIfAvailable(ctx context.Context, logger log.Logger) { - newerBinary, err := latestLauncherPath(ctx, logger) +func runNewerLauncherIfAvailable(ctx context.Context, slogger *slog.Logger) { + newerBinary, err := latestLauncherPath(ctx, slogger) if err != nil { - level.Error(logger).Log( - "msg", "could not check out latest launcher, will fall back to old autoupdate library", + slogger.Log(ctx, slog.LevelError, + "could not check out latest launcher, will fall back to old autoupdate library", "err", err, ) @@ -183,35 +182,46 @@ func runNewerLauncherIfAvailable(ctx context.Context, logger log.Logger) { } if newerBinary == "" { - level.Info(logger).Log("msg", "nothing newer") + slogger.Log(ctx, slog.LevelInfo, + "nothing newer", + ) return } - level.Info(logger).Log( - "msg", "preparing to exec new binary", + slogger.Log(ctx, slog.LevelInfo, + "preparing to exec new binary", "old_version", version.Version().Version, "new_binary", newerBinary, ) if err := execwrapper.Exec(ctx, newerBinary, os.Args, os.Environ()); err != nil { - logutil.Fatal(logger, "msg", "error execing newer version of launcher", "new_binary", newerBinary, "err", err) + slogger.Log(ctx, slog.LevelError, + "error execing newer version of launcher", + "new_binary", newerBinary, + "err", err, + ) + os.Exit(1) } - logutil.Fatal(logger, "msg", "execing newer version of launcher exited unexpectedly without error", "new_binary", newerBinary) + slogger.Log(ctx, slog.LevelError, + "execing newer version of launcher exited unexpectedly without error", + "new_binary", newerBinary, + ) + os.Exit(1) } // latestLauncherPath looks for the latest version of launcher in the new autoupdate library, // falling back to the old library if necessary. -func latestLauncherPath(ctx context.Context, logger log.Logger) (string, error) { - newerBinary, err := tuf.CheckOutLatestWithoutConfig("launcher", logger) +func latestLauncherPath(ctx context.Context, slogger *slog.Logger) (string, error) { + newerBinary, err := tuf.CheckOutLatestWithoutConfig("launcher", slogger) if err != nil { return "", fmt.Errorf("checking out latest launcher: %w", err) } currentPath, _ := os.Executable() if newerBinary.Version != version.Version().Version && newerBinary.Path != currentPath { - level.Info(logger).Log( - "msg", "got new version of launcher to run", + slogger.Log(ctx, slog.LevelInfo, + "got new version of launcher to run", "old_version", version.Version().Version, "new_binary_version", newerBinary.Version, "new_binary_path", newerBinary.Path, diff --git a/ee/agent/knapsack/knapsack.go b/ee/agent/knapsack/knapsack.go index 325a3bd12..f5cd274ff 100644 --- a/ee/agent/knapsack/knapsack.go +++ b/ee/agent/knapsack/knapsack.go @@ -9,7 +9,6 @@ import ( "log/slog" - "github.com/go-kit/kit/log" "github.com/kolide/launcher/ee/agent/storage" "github.com/kolide/launcher/ee/agent/types" "github.com/kolide/launcher/ee/tuf" @@ -43,6 +42,13 @@ type knapsack struct { } func New(stores map[storage.Store]types.KVStore, flags types.Flags, db *bbolt.DB, slogger, systemSlogger *multislogger.MultiSlogger) *knapsack { + if slogger == nil { + slogger = multislogger.New() + } + if systemSlogger == nil { + systemSlogger = multislogger.New() + } + k := &knapsack{ db: db, flags: flags, @@ -141,7 +147,7 @@ func (k *knapsack) getKVStore(storeType storage.Store) types.KVStore { } func (k *knapsack) LatestOsquerydPath(ctx context.Context) string { - latestBin, err := tuf.CheckOutLatest(ctx, "osqueryd", k.RootDirectory(), k.UpdateDirectory(), k.UpdateChannel(), log.NewNopLogger()) + latestBin, err := tuf.CheckOutLatest(ctx, "osqueryd", k.RootDirectory(), k.UpdateDirectory(), k.UpdateChannel(), k.Slogger()) if err != nil { return autoupdate.FindNewest(ctx, k.OsquerydPath()) } diff --git a/ee/debug/checkups/tuf.go b/ee/debug/checkups/tuf.go index c5c026c17..d88ce4038 100644 --- a/ee/debug/checkups/tuf.go +++ b/ee/debug/checkups/tuf.go @@ -11,9 +11,9 @@ import ( "path/filepath" "runtime" - "github.com/go-kit/kit/log" "github.com/kolide/launcher/ee/agent/types" "github.com/kolide/launcher/ee/tuf" + "github.com/kolide/launcher/pkg/log/multislogger" ) type ( @@ -196,14 +196,16 @@ func (tc *tufCheckup) selectedVersions() map[string]map[string]string { "osqueryd": make(map[string]string), } - if launcherVersion, err := tuf.CheckOutLatestWithoutConfig("launcher", log.NewNopLogger()); err != nil { + nopLogger := multislogger.New().Logger + + if launcherVersion, err := tuf.CheckOutLatestWithoutConfig("launcher", nopLogger); err != nil { selectedVersions["launcher"]["path"] = fmt.Sprintf("error checking out latest version: %v", err) } else { selectedVersions["launcher"]["path"] = launcherVersion.Path selectedVersions["launcher"]["version"] = launcherVersion.Version } - if osquerydVersion, err := tuf.CheckOutLatestWithoutConfig("osqueryd", log.NewNopLogger()); err != nil { + if osquerydVersion, err := tuf.CheckOutLatestWithoutConfig("osqueryd", nopLogger); err != nil { selectedVersions["osqueryd"]["path"] = fmt.Sprintf("error checking out latest version: %v", err) } else { selectedVersions["osqueryd"]["path"] = osquerydVersion.Path diff --git a/ee/tuf/library_lookup.go b/ee/tuf/library_lookup.go index 9917a1e36..b361ff59c 100644 --- a/ee/tuf/library_lookup.go +++ b/ee/tuf/library_lookup.go @@ -4,13 +4,12 @@ import ( "context" "errors" "fmt" + "log/slog" "os" "path/filepath" "strings" "github.com/Masterminds/semver" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "github.com/kolide/launcher/pkg/autoupdate" "github.com/kolide/launcher/pkg/launcher" "github.com/kolide/launcher/pkg/traces" @@ -32,8 +31,8 @@ type autoupdateConfig struct { // CheckOutLatestWithoutConfig returns information about the latest downloaded executable for our binary, // searching for launcher configuration values in its config file. -func CheckOutLatestWithoutConfig(binary autoupdatableBinary, logger log.Logger) (*BinaryUpdateInfo, error) { - logger = log.With(logger, "component", "tuf_library_lookup") +func CheckOutLatestWithoutConfig(binary autoupdatableBinary, slogger *slog.Logger) (*BinaryUpdateInfo, error) { + slogger = slogger.With("component", "tuf_library_lookup") cfg, err := getAutoupdateConfig(os.Args[1:]) if err != nil { return nil, fmt.Errorf("could not get autoupdate config: %w", err) @@ -44,7 +43,7 @@ func CheckOutLatestWithoutConfig(binary autoupdatableBinary, logger log.Logger) return &BinaryUpdateInfo{Path: cfg.localDevelopmentPath}, nil } - return CheckOutLatest(context.Background(), binary, cfg.rootDirectory, cfg.updateDirectory, cfg.channel, logger) + return CheckOutLatest(context.Background(), binary, cfg.rootDirectory, cfg.updateDirectory, cfg.channel, slogger) } // getAutoupdateConfig pulls the configuration values necessary to work with the autoupdate library @@ -141,7 +140,7 @@ func getAutoupdateConfigFromFile(configFilePath string) (*autoupdateConfig, erro // CheckOutLatest returns the path to the latest downloaded executable for our binary, as well // as its version. -func CheckOutLatest(ctx context.Context, binary autoupdatableBinary, rootDirectory string, updateDirectory string, channel string, logger log.Logger) (*BinaryUpdateInfo, error) { +func CheckOutLatest(ctx context.Context, binary autoupdatableBinary, rootDirectory string, updateDirectory string, channel string, slogger *slog.Logger) (*BinaryUpdateInfo, error) { ctx, span := traces.StartSpan(ctx, "binary", string(binary)) defer span.End() @@ -152,11 +151,18 @@ func CheckOutLatest(ctx context.Context, binary autoupdatableBinary, rootDirecto update, err := findExecutableFromRelease(ctx, binary, LocalTufDirectory(rootDirectory), channel, updateDirectory) if err == nil { span.AddEvent("found_latest_from_release") - level.Info(logger).Log("msg", "found executable matching current release", "executable_path", update.Path, "executable_version", update.Version) + slogger.Log(ctx, slog.LevelInfo, + "found executable matching current release", + "executable_path", update.Path, + "executable_version", update.Version, + ) return update, nil } - level.Info(logger).Log("msg", "could not find executable matching current release", "err", err) + slogger.Log(ctx, slog.LevelInfo, + "could not find executable matching current release", + "err", err, + ) // If we can't find the specific release version that we should be on, then just return the executable // with the most recent version in the library diff --git a/ee/tuf/library_lookup_test.go b/ee/tuf/library_lookup_test.go index ccbcbae30..39ced74a0 100644 --- a/ee/tuf/library_lookup_test.go +++ b/ee/tuf/library_lookup_test.go @@ -7,8 +7,8 @@ import ( "path/filepath" "testing" - "github.com/go-kit/kit/log" tufci "github.com/kolide/launcher/ee/tuf/ci" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/stretchr/testify/require" ) @@ -45,7 +45,7 @@ func TestCheckOutLatest_withTufRepository(t *testing.T) { require.NoError(t, os.Chmod(tooRecentPath, 0755)) // Check it - latest, err := CheckOutLatest(context.TODO(), binary, rootDir, "", "nightly", log.NewNopLogger()) + latest, err := CheckOutLatest(context.TODO(), binary, rootDir, "", "nightly", multislogger.New().Logger) require.NoError(t, err, "unexpected error on checking out latest") require.Equal(t, executablePath, latest.Path) require.Equal(t, executableVersion, latest.Version) @@ -72,7 +72,7 @@ func TestCheckOutLatest_withoutTufRepository(t *testing.T) { require.NoError(t, err, "did not make test binary") // Check it - latest, err := CheckOutLatest(context.TODO(), binary, rootDir, "", "nightly", log.NewNopLogger()) + latest, err := CheckOutLatest(context.TODO(), binary, rootDir, "", "nightly", multislogger.New().Logger) require.NoError(t, err, "unexpected error on checking out latest") require.Equal(t, executablePath, latest.Path) require.Equal(t, executableVersion, latest.Version) diff --git a/pkg/osquery/runtime/osqueryinstance.go b/pkg/osquery/runtime/osqueryinstance.go index 3459ff26d..e1da99e19 100644 --- a/pkg/osquery/runtime/osqueryinstance.go +++ b/pkg/osquery/runtime/osqueryinstance.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "log/slog" "os" "os/exec" "path/filepath" @@ -14,11 +15,10 @@ import ( "sync" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "github.com/kolide/launcher/ee/agent" "github.com/kolide/launcher/ee/agent/types" "github.com/kolide/launcher/pkg/backoff" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/kolide/launcher/pkg/osquery/runtime/history" "github.com/kolide/launcher/pkg/traces" "github.com/osquery/osquery-go" @@ -135,11 +135,11 @@ func WithStderr(w io.Writer) OsqueryInstanceOption { } } -// WithLogger is a functional option which allows the user to pass a log.Logger +// WithSlogger is a functional option which allows the user to pass a *slog.Logger // to be used for logging osquery instance status. -func WithLogger(logger log.Logger) OsqueryInstanceOption { +func WithSlogger(slogger *slog.Logger) OsqueryInstanceOption { return func(i *OsqueryInstance) { - i.logger = logger + i.slogger = slogger } } @@ -222,8 +222,8 @@ func WithKnapsack(k types.Knapsack) OsqueryInstanceOption { // OsqueryInstance is the type which represents a currently running instance // of osqueryd. type OsqueryInstance struct { - opts osqueryOptions - logger log.Logger + opts osqueryOptions + slogger *slog.Logger // the following are instance artifacts that are created and held as a result // of launching an osqueryd process errgroup *errgroup.Group @@ -358,7 +358,7 @@ func newInstance() *OsqueryInstance { i.cancel = cancel i.errgroup, i.doneCtx = errgroup.WithContext(ctx) - i.logger = log.NewNopLogger() + i.slogger = multislogger.New().Logger i.startFunc = func(cmd *exec.Cmd) error { return cmd.Start() @@ -544,9 +544,10 @@ func (o *OsqueryInstance) StartOsqueryClient(paths *osqueryFilePaths) (*osquery. // startOsqueryExtensionManagerServer takes a set of plugins, creates // an osquery.NewExtensionManagerServer for them, and then starts it. func (o *OsqueryInstance) StartOsqueryExtensionManagerServer(name string, socketPath string, client *osquery.ExtensionManagerClient, plugins []osquery.OsqueryPlugin) error { - logger := log.With(o.logger, "extensionMangerServer", name) - - level.Debug(logger).Log("msg", "Starting startOsqueryExtensionManagerServer") + o.slogger.Log(context.TODO(), slog.LevelDebug, + "starting startOsqueryExtensionManagerServer", + "extension_name", name, + ) var extensionManagerServer *osquery.ExtensionManagerServer if err := backoff.WaitFor(func() error { @@ -559,7 +560,11 @@ func (o *OsqueryInstance) StartOsqueryExtensionManagerServer(name string, socket ) return newErr }, socketOpenTimeout, socketOpenInterval); err != nil { - level.Debug(logger).Log("msg", "could not create an extension server", "err", err) + o.slogger.Log(context.TODO(), slog.LevelDebug, + "could not create an extension server", + "extension_name", name, + "err", err, + ) return fmt.Errorf("could not create an extension server: %w", err) } @@ -572,10 +577,18 @@ func (o *OsqueryInstance) StartOsqueryExtensionManagerServer(name string, socket // Start! o.errgroup.Go(func() error { - defer level.Info(o.logger).Log("msg", "exiting errgroup", "errgroup", "run extension manager server", "extension_name", name) + defer o.slogger.Log(context.TODO(), slog.LevelDebug, + "exiting errgroup", + "errgroup", "run extension manager server", + "extension_name", name, + ) if err := extensionManagerServer.Start(); err != nil { - level.Info(logger).Log("msg", "Extension manager server startup got error", "err", err, "extension_name", name) + o.slogger.Log(context.TODO(), slog.LevelInfo, + "extension manager server startup got error", + "err", err, + "extension_name", name, + ) return fmt.Errorf("running extension server: %w", err) } return errors.New("extension manager server exited") @@ -583,13 +596,23 @@ func (o *OsqueryInstance) StartOsqueryExtensionManagerServer(name string, socket // register a shutdown routine o.errgroup.Go(func() error { - defer level.Info(o.logger).Log("msg", "exiting errgroup", "errgroup", "shut down extension manager server", "extension_name", name) + defer o.slogger.Log(context.TODO(), slog.LevelDebug, + "exiting errgroup", + "errgroup", "shut down extension manager server", + "extension_name", name, + ) <-o.doneCtx.Done() - level.Debug(logger).Log("msg", "Starting extension shutdown") + + o.slogger.Log(context.TODO(), slog.LevelDebug, + "exiting errgroup", + "errgroup", "starting extension shutdown", + "extension_name", name, + ) + if err := extensionManagerServer.Shutdown(context.TODO()); err != nil { - level.Info(o.logger).Log( - "msg", "Got error while shutting down extension server", + o.slogger.Log(context.TODO(), slog.LevelInfo, + "got error while shutting down extension server", "err", err, "extension_name", name, ) @@ -597,7 +620,10 @@ func (o *OsqueryInstance) StartOsqueryExtensionManagerServer(name string, socket return o.doneCtx.Err() }) - level.Debug(logger).Log("msg", "Clean finish startOsqueryExtensionManagerServer") + o.slogger.Log(context.TODO(), slog.LevelDebug, + "clean finish startOsqueryExtensionManagerServer", + "extension_name", name, + ) return nil } diff --git a/pkg/osquery/runtime/runner.go b/pkg/osquery/runtime/runner.go index 0f0eece90..9f6120876 100644 --- a/pkg/osquery/runtime/runner.go +++ b/pkg/osquery/runtime/runner.go @@ -18,7 +18,6 @@ import ( "github.com/kolide/launcher/ee/tuf" "github.com/kolide/launcher/pkg/autoupdate" "github.com/kolide/launcher/pkg/backoff" - "github.com/kolide/launcher/pkg/contexts/ctxlog" "github.com/kolide/launcher/pkg/osquery/runtime/history" "github.com/kolide/launcher/pkg/osquery/table" "github.com/kolide/launcher/pkg/traces" @@ -316,14 +315,14 @@ func (r *Runner) launchOsqueryInstance() error { // FindNewest uses context as a way to get a logger, so we need to // create and pass a ctxlog in. var currentOsquerydBinaryPath string - currentOsquerydBinary, err := tuf.CheckOutLatest(ctx, "osqueryd", o.opts.rootDirectory, o.opts.updateDirectory, o.opts.updateChannel, o.logger) + currentOsquerydBinary, err := tuf.CheckOutLatest(ctx, "osqueryd", o.opts.rootDirectory, o.opts.updateDirectory, o.opts.updateChannel, r.slogger) if err != nil { r.slogger.Log(ctx, slog.LevelDebug, "could not get latest version of osqueryd from new autoupdate library, falling back", "err", err, ) currentOsquerydBinaryPath = autoupdate.FindNewest( - ctxlog.NewContext(ctx, o.logger), + ctx, o.opts.binaryPath, autoupdate.DeleteOldUpdates(), ) diff --git a/pkg/osquery/runtime/runtime_test.go b/pkg/osquery/runtime/runtime_test.go index 44e4cb287..24cac4db1 100644 --- a/pkg/osquery/runtime/runtime_test.go +++ b/pkg/osquery/runtime/runtime_test.go @@ -670,7 +670,7 @@ func TestOsquerySlowStart(t *testing.T) { WithKnapsack(k), WithRootDirectory(rootDirectory), WithOsquerydBinary(testOsqueryBinaryDirectory), - WithLogger(log.NewLogfmtLogger(&logBytes)), + WithSlogger(slogger.Logger), WithStartFunc(func(cmd *exec.Cmd) error { err := cmd.Start() if err != nil {