adds std lib slog logger to knapsack (#1419)

cmd/grpc.ext/grpc.go

@@ -100,7 +100,7 @@ func main() {
 		logutil.Fatal(logger, "err", fmt.Errorf("creating stores: %w", err), "stack", fmt.Sprintf("%+v", err))
 	}
 	f := flags.NewFlagController(logger, stores[storage.AgentFlagsStore])
-	k := knapsack.New(stores, f, db)
+	k := knapsack.New(stores, f, db, nil, nil)
 
 	ext, err := grpcext.NewExtension(remote, k, extOpts)
 	if err != nil {

cmd/launcher/doctor.go

@@ -26,7 +26,7 @@ func runDoctor(args []string) error {
 	fcOpts := []flags.Option{flags.WithCmdLineOpts(opts)}
 	logger := log.With(logutil.NewCLILogger(true), "caller", log.DefaultCaller)
 	flagController := flags.NewFlagController(logger, nil, fcOpts...)
-	k := knapsack.New(nil, flagController, nil)
+	k := knapsack.New(nil, flagController, nil, nil, nil)
 
 	w := os.Stdout //tabwriter.NewWriter(os.Stdout, 0, 8, 1, '\t', tabwriter.AlignRight)
 

cmd/launcher/flare.go

@@ -50,7 +50,7 @@ func runFlare(args []string) error {
 	fcOpts := []flags.Option{flags.WithCmdLineOpts(opts)}
 	flagController := flags.NewFlagController(logger, inmemory.NewStore(logger), fcOpts...)
 
-	k := knapsack.New(nil, flagController, nil)
+	k := knapsack.New(nil, flagController, nil, nil, nil)
 	ctx := context.Background()
 
 	type flareDestinationTyp interface {

cmd/launcher/launcher.go

@@ -7,6 +7,7 @@ import (
 	"crypto/x509"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -45,6 +46,7 @@ import (
 	"github.com/kolide/launcher/pkg/debug/checkups"
 	"github.com/kolide/launcher/pkg/launcher"
 	"github.com/kolide/launcher/pkg/log/logshipper"
+	"github.com/kolide/launcher/pkg/log/multislogger"
 	"github.com/kolide/launcher/pkg/log/teelogger"
 	"github.com/kolide/launcher/pkg/osquery"
 	"github.com/kolide/launcher/pkg/osquery/runsimple"
@@ -68,10 +70,11 @@ const (
 // runLauncher is the entry point into running launcher. It creates a
 // rungroups with the various options, and goes! If autoupdate is
 // enabled, the finalizers will trigger various restarts.
-func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) error {
+func runLauncher(ctx context.Context, cancel func(), slogger, systemSlogger *multislogger.MultiSlogger, opts *launcher.Options) error {
 	thrift.ServerConnectivityCheckInterval = 100 * time.Millisecond
 
-	logger := log.With(ctxlog.FromContext(ctx), "caller", log.DefaultCaller, "session_pid", os.Getpid())
+	logger := ctxlog.FromContext(ctx)
+	logger = log.With(logger, "caller", log.DefaultCaller, "session_pid", os.Getpid())
 
 	go runOsqueryVersionCheck(ctx, logger, opts.OsquerydPath)
 
@@ -166,7 +169,15 @@ func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) err
 
 	fcOpts := []flags.Option{flags.WithCmdLineOpts(opts)}
 	flagController := flags.NewFlagController(logger, stores[storage.AgentFlagsStore], fcOpts...)
-	k := knapsack.New(stores, flagController, db)
+	k := knapsack.New(stores, flagController, db, slogger, systemSlogger)
+
+	if k.Debug() {
+		// If we're in debug mode, then we assume we want to echo _all_ logs to stderr.
+		k.AddSlogHandler(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
+			AddSource: true,
+			Level:     slog.LevelDebug,
+		}))
+	}
 
 	// Need to set up the log shipper so that we can get the logger early
 	// and pass it to the various systems.
@@ -175,6 +186,7 @@ func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) err
 		logShipper = logshipper.New(k, logger)
 		logger = teelogger.New(logger, logShipper)
 		logger = log.With(logger, "caller", log.Caller(5))
+		k.AddSlogHandler(logShipper.SlogHandler())
 		ctx = ctxlog.NewContext(ctx, logger) // Set the logger back in the ctx
 	}
 
@@ -261,8 +273,7 @@ func runLauncher(ctx context.Context, cancel func(), opts *launcher.Options) err
 	runGroup.Add("osqueryExtension", extension.Execute, extension.Interrupt)
 
 	versionInfo := version.Version()
-	level.Info(logger).Log(
-		"msg", "started kolide launcher",
+	k.SystemSlogger().Info("started kolide launcher",
 		"version", versionInfo.Version,
 		"build", versionInfo.Revision,
 	)

cmd/launcher/main.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"flag"
 	"fmt"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"strings"
@@ -21,6 +22,7 @@ import (
 	"github.com/kolide/launcher/pkg/execwrapper"
 	"github.com/kolide/launcher/pkg/launcher"
 	"github.com/kolide/launcher/pkg/log/locallogger"
+	"github.com/kolide/launcher/pkg/log/multislogger"
 	"github.com/kolide/launcher/pkg/log/teelogger"
 )
 
@@ -97,9 +99,30 @@ func main() {
 	// recreate the logger with  the appropriate level.
 	logger = logutil.NewServerLogger(opts.Debug)
 
+	// set up system slogger to write to os logs
+	systemSlogger := new(multislogger.MultiSlogger)
+	systemSlogger.AddHandler(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
+	// set up slogger for internal launcher logging
+	slogger := new(multislogger.MultiSlogger)
+
 	// Create a local logger. This logs to a known path, and aims to help diagnostics
 	if opts.RootDirectory != "" {
-		logger = teelogger.New(logger, locallogger.NewKitLogger(filepath.Join(opts.RootDirectory, "debug.json")))
+		localLogger := locallogger.NewKitLogger(filepath.Join(opts.RootDirectory, "debug.json"))
+		logger = teelogger.New(logger, localLogger)
+
+		localSloggerHandler := slog.NewJSONHandler(localLogger.Writer(), &slog.HandlerOptions{
+			AddSource: true,
+			Level:     slog.LevelDebug,
+		})
+
+		slogger.AddHandler(localSloggerHandler)
+
+		// also send system logs to localSloggerHandler
+		systemSlogger.AddHandler(localSloggerHandler)
+
 		locallogger.CleanUpRenamedDebugLogs(opts.RootDirectory, logger)
 	}
 
@@ -115,7 +138,7 @@ func main() {
 
 	ctx = ctxlog.NewContext(ctx, logger)
 
-	if err := runLauncher(ctx, cancel, opts); err != nil {
+	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)

cmd/launcher/svc_windows.go

@@ -6,6 +6,7 @@ package main
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"time"
@@ -19,6 +20,7 @@ import (
 	"github.com/kolide/launcher/pkg/launcher"
 	"github.com/kolide/launcher/pkg/log/eventlog"
 	"github.com/kolide/launcher/pkg/log/locallogger"
+	"github.com/kolide/launcher/pkg/log/multislogger"
 	"github.com/kolide/launcher/pkg/log/teelogger"
 
 	"golang.org/x/sys/windows/svc"
@@ -60,9 +62,28 @@ func runWindowsSvc(args []string) error {
 		logger = level.NewFilter(logger, level.AllowInfo())
 	}
 
+	systemSlogger := new(multislogger.MultiSlogger)
+	systemSlogger.AddHandler(slog.NewJSONHandler(eventLogWriter, &slog.HandlerOptions{
+		Level: slog.LevelInfo,
+	}))
+
+	localSlogger := new(multislogger.MultiSlogger)
+
 	// Create a local logger. This logs to a known path, and aims to help diagnostics
 	if opts.RootDirectory != "" {
-		logger = teelogger.New(logger, locallogger.NewKitLogger(filepath.Join(opts.RootDirectory, "debug.json")))
+		ll := locallogger.NewKitLogger(filepath.Join(opts.RootDirectory, "debug.json"))
+		logger = teelogger.New(logger, ll)
+
+		localSloggerHandler := slog.NewJSONHandler(ll.Writer(), &slog.HandlerOptions{
+			AddSource: true,
+			Level:     slog.LevelDebug,
+		})
+
+		localSlogger.AddHandler(localSloggerHandler)
+
+		// also write system logs to localSloggerHandler
+		systemSlogger.AddHandler(localSloggerHandler)
+
 		locallogger.CleanUpRenamedDebugLogs(opts.RootDirectory, logger)
 	}
 
@@ -99,7 +120,12 @@ func runWindowsSvc(args []string) error {
 		}
 	}()
 
-	if err := svc.Run(serviceName, &winSvc{logger: logger, opts: opts}); err != nil {
+	if err := svc.Run(serviceName, &winSvc{
+		logger:        logger,
+		slogger:       localSlogger,
+		systemSlogger: systemSlogger,
+		opts:          opts,
+	}); err != nil {
 		// TODO The caller doesn't have the event log configured, so we
 		// need to log here. this implies we need some deeper refactoring
 		// of the logging
@@ -140,8 +166,9 @@ func runWindowsSvcForeground(args []string) error {
 }
 
 type winSvc struct {
-	logger log.Logger
-	opts   *launcher.Options
+	logger                 log.Logger
+	slogger, systemSlogger *multislogger.MultiSlogger
+	opts                   *launcher.Options
 }
 
 func (w *winSvc) Execute(args []string, r <-chan svc.ChangeRequest, changes chan<- svc.Status) (ssec bool, errno uint32) {
@@ -156,7 +183,7 @@ func (w *winSvc) Execute(args []string, r <-chan svc.ChangeRequest, changes chan
 	ctx = ctxlog.NewContext(ctx, w.logger)
 
 	go func() {
-		err := runLauncher(ctx, cancel, w.opts)
+		err := runLauncher(ctx, cancel, w.slogger, w.systemSlogger, w.opts)
 		if err != nil {
 			level.Info(w.logger).Log("msg", "runLauncher exited", "err", err)
 			level.Debug(w.logger).Log("msg", "runLauncher exited", "err", err, "stack", fmt.Sprintf("%+v", err))

go.mod

@@ -66,6 +66,7 @@ require (
 	github.com/cenkalti/backoff/v4 v4.2.1 // indirect
 	github.com/felixge/httpsnoop v1.0.3 // indirect
 	github.com/grpc-ecosystem/grpc-gateway/v2 v2.18.0 // indirect
+	github.com/samber/lo v1.38.1 // indirect
 	go.opentelemetry.io/proto/otlp v1.0.0 // indirect
 	google.golang.org/genproto/googleapis/api v0.0.0-20231012201019-e917dd12ba7a // indirect
 	google.golang.org/genproto/googleapis/rpc v0.0.0-20231012201019-e917dd12ba7a // indirect
@@ -108,6 +109,7 @@ require (
 	github.com/opencontainers/image-spec v1.0.2 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/power-devops/perfstat v0.0.0-20210106213030-5aafc221ea8c // indirect
+	github.com/samber/slog-multi v1.0.2
 	github.com/secure-systems-lab/go-securesystemslib v0.5.0 // indirect
 	github.com/shoenig/go-m1cpu v0.1.6 // indirect
 	github.com/smartystreets/goconvey v1.6.4 // indirect

go.sum

@@ -429,6 +429,10 @@ github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncj
 github.com/russross/blackfriday v1.5.2/go.mod h1:JO/DiYxRf+HjHt06OyowR9PTA263kcR/rfWxYHBV53g=
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
+github.com/samber/lo v1.38.1 h1:j2XEAqXKb09Am4ebOg31SpvzUTTs6EN3VfgeLUhPdXM=
+github.com/samber/lo v1.38.1/go.mod h1:+m/ZKRl6ClXCE2Lgf3MsQlWfh4bn1bz6CXEOxnEXnEA=
+github.com/samber/slog-multi v1.0.2 h1:6BVH9uHGAsiGkbbtQgAOQJMpKgV8unMrHhhJaw+X1EQ=
+github.com/samber/slog-multi v1.0.2/go.mod h1:uLAvHpGqbYgX4FSL0p1ZwoLuveIAJvBECtE07XmYvFo=
 github.com/scjalliance/comshim v0.0.0-20190308082608-cf06d2532c4e h1:+/AzLkOdIXEPrAQtwAeWOBnPQ0BnYlBW0aCZmSb47u4=
 github.com/scjalliance/comshim v0.0.0-20190308082608-cf06d2532c4e/go.mod h1:9Tc1SKnfACJb9N7cw2eyuI6xzy845G7uZONBsi5uPEA=
 github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc=

pkg/agent/flags/flag_controller.go

@@ -2,6 +2,7 @@ package flags
 
 import (
 	"errors"
+	"strings"
 	"sync"
 	"time"
 
@@ -485,6 +486,26 @@ func (fc *FlagController) LogIngestServerURL() string {
 	).get(fc.getControlServerValue(keys.LogIngestServerURL))
 }
 
+// LogShippingLevel is the level at which logs should be shipped to the server
+func (fc *FlagController) SetLogShippingLevel(level string) error {
+	return fc.setControlServerValue(keys.LogShippingLevel, []byte(level))
+}
+func (fc *FlagController) LogShippingLevel() string {
+	return NewStringFlagValue(
+		WithDefaultString("error"),
+		WithSanitizer(func(value string) string {
+			value = strings.ToLower(value)
+
+			switch value {
+			case "debug", "info", "warn":
+				return value
+			default:
+				return "error"
+			}
+		}),
+	).get(fc.getControlServerValue(keys.LogShippingLevel))
+}
+
 func (fc *FlagController) SetTraceIngestServerURL(url string) error {
 	return fc.setControlServerValue(keys.TraceIngestServerURL, []byte(url))
 }

pkg/agent/flags/keys/keys.go

@@ -47,6 +47,7 @@ const (
 	TraceSamplingRate              FlagKey = "trace_sampling_rate"
 	TraceBatchTimeout              FlagKey = "trace_batch_timeout"
 	LogIngestServerURL             FlagKey = "log_ingest_url"
+	LogShippingLevel               FlagKey = "log_shipping_level"
 	TraceIngestServerURL           FlagKey = "trace_ingest_url"
 	DisableTraceIngestTLS          FlagKey = "disable_trace_ingest_tls"
 	InModernStandby                FlagKey = "in_modern_standby"

pkg/agent/knapsack/knapsack.go

@@ -4,12 +4,15 @@ import (
 	"context"
 	"time"
 
+	"log/slog"
+
 	"github.com/go-kit/kit/log"
 	"github.com/kolide/launcher/pkg/agent/flags/keys"
 	"github.com/kolide/launcher/pkg/agent/storage"
 	"github.com/kolide/launcher/pkg/agent/types"
 	"github.com/kolide/launcher/pkg/autoupdate"
 	"github.com/kolide/launcher/pkg/autoupdate/tuf"
+	"github.com/kolide/launcher/pkg/log/multislogger"
 	"go.etcd.io/bbolt"
 )
 
@@ -26,23 +29,42 @@ type knapsack struct {
 	// remove this field and prevent "leaking" bbolt into places it doesn't need to.
 	db *bbolt.DB
 
+	slogger, systemSlogger *multislogger.MultiSlogger
+
 	// This struct is a work in progress, and will be iteratively added to as needs arise.
 	// Some potential future additions include:
 	// Querier
 }
 
-func New(stores map[storage.Store]types.KVStore, flags types.Flags, db *bbolt.DB) *knapsack {
+func New(stores map[storage.Store]types.KVStore, flags types.Flags, db *bbolt.DB, slogger, systemSlogger *multislogger.MultiSlogger) *knapsack {
 	k := &knapsack{
-		db:     db,
-		flags:  flags,
-		stores: stores,
+		db:            db,
+		flags:         flags,
+		stores:        stores,
+		slogger:       slogger,
+		systemSlogger: systemSlogger,
 	}
 
 	return k
 }
 
-// BboltDB interface methods
+// Logging interface methods
+func (k *knapsack) Slogger() *slog.Logger {
+	return k.slogger.Logger
+}
+
+func (k *knapsack) SystemSlogger() *slog.Logger {
+	return k.systemSlogger.Logger
+}
+
+func (k *knapsack) AddSlogHandler(handler ...slog.Handler) {
+	k.slogger = k.slogger.AddHandler(handler...)
 
+	// also send system logs to the same handlers
+	k.systemSlogger = k.systemSlogger.AddHandler(handler...)
+}
+
+// BboltDB interface methods
 func (k *knapsack) BboltDB() *bbolt.DB {
 	return k.db
 }
@@ -407,6 +429,13 @@ func (k *knapsack) LogIngestServerURL() string {
 	return k.flags.LogIngestServerURL()
 }
 
+func (k *knapsack) SetLogShippingLevel(level string) error {
+	return k.flags.SetLogShippingLevel(level)
+}
+func (k *knapsack) LogShippingLevel() string {
+	return k.flags.LogShippingLevel()
+}
+
 func (k *knapsack) SetInModernStandby(enabled bool) error {
 	return k.flags.SetInModernStandby(enabled)
 }

pkg/agent/types/flags.go

@@ -181,6 +181,10 @@ type Flags interface {
 	SetLogIngestServerURL(url string) error
 	LogIngestServerURL() string
 
+	// LogShippingLevel is the level at which logs should be shipped to the server
+	SetLogShippingLevel(level string) error
+	LogShippingLevel() string
+
 	// TraceIngestServerURL is the URL of the ingest server for traces
 	SetTraceIngestServerURL(url string) error
 	TraceIngestServerURL() string

pkg/agent/types/knapsack.go

@@ -8,6 +8,7 @@ type Knapsack interface {
 	Stores
 	BboltDB
 	Flags
+	Slogger
 	// LatestOsquerydPath finds the path to the latest osqueryd binary, after accounting for updates.
 	LatestOsquerydPath(ctx context.Context) string
 }