diff --git a/cmd/launcher/main.go b/cmd/launcher/main.go index 710a7b14f..e7ae226a4 100644 --- a/cmd/launcher/main.go +++ b/cmd/launcher/main.go @@ -7,7 +7,9 @@ import ( "os" "strings" "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" @@ -15,6 +17,7 @@ import ( "github.com/kolide/launcher/pkg/autoupdate" "github.com/kolide/launcher/pkg/contexts/ctxlog" "github.com/kolide/launcher/pkg/execwrapper" + "github.com/kolide/launcher/pkg/log/teelogger" "github.com/pkg/errors" ) @@ -86,6 +89,33 @@ func main() { // recreate the logger with the appropriate level. logger = logutil.NewServerLogger(opts.Debug) + + if opts.DebugLogFile != "" { + logMirror, err := os.OpenFile(opts.DebugLogFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + level.Info(logger).Log("msg", "failed to create file logger", "err", err) + os.Exit(2) + } + defer logMirror.Close() + + fileLogger := log.NewJSONLogger(log.NewSyncWriter(logMirror)) + fileLogger = log.With(fileLogger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + + logger = teelogger.New(logger, fileLogger) + + level.Info(logger).Log("msg", "mirroring logs to file", "file", logMirror.Name()) + } + + defer func() { + if r := recover(); r != nil { + level.Info(logger).Log( + "msg", "panic occurred", + "err", err, + ) + time.Sleep(time.Second) + } + }() + ctx = ctxlog.NewContext(ctx, logger) if err := runLauncher(ctx, cancel, opts); err != nil { diff --git a/cmd/launcher/options.go b/cmd/launcher/options.go index e27b02488..de28aee66 100644 --- a/cmd/launcher/options.go +++ b/cmd/launcher/options.go @@ -72,6 +72,7 @@ func parseOptions(args []string) (*launcher.Options, error) { // Development options flDebug = flagset.Bool("debug", false, "Whether or not debug logging is enabled (default: false)") + flDebugLogFile = flagset.String("debug_log_file", "", "File to mirror debug logs to (optional)") flOsqueryVerbose = flagset.Bool("osquery_verbose", false, "Enable verbose osqueryd (default: false)") flDeveloperUsage = flagset.Bool("dev_help", false, "Print full Launcher help, including developer options") flDisableControlTLS = flagset.Bool("disable_control_tls", false, "Disable TLS encryption for the control features") @@ -147,30 +148,31 @@ func parseOptions(args []string) (*launcher.Options, error) { } opts := &launcher.Options{ - KolideServerURL: *flKolideServerURL, - Transport: *flTransport, + Autoupdate: *flAutoupdate, + AutoupdateInterval: *flAutoupdateInterval, + CertPins: certPins, Control: *flControl, ControlServerURL: *flControlServerURL, - GetShellsInterval: *flGetShellsInterval, - EnrollSecret: *flEnrollSecret, - EnrollSecretPath: *flEnrollSecretPath, - RootDirectory: *flRootDirectory, - OsquerydPath: osquerydPath, - CertPins: certPins, - RootPEM: *flRootPEM, - LoggingInterval: *flLoggingInterval, - EnableInitialRunner: *flInitialRunner, - Autoupdate: *flAutoupdate, Debug: *flDebug, - OsqueryVerbose: *flOsqueryVerbose, - OsqueryFlags: flOsqueryFlags, + DebugLogFile: *flDebugLogFile, DisableControlTLS: *flDisableControlTLS, + EnableInitialRunner: *flInitialRunner, + EnrollSecret: *flEnrollSecret, + EnrollSecretPath: *flEnrollSecretPath, + GetShellsInterval: *flGetShellsInterval, InsecureTLS: *flInsecureTLS, InsecureTransport: *flInsecureTransport, - NotaryServerURL: *flNotaryServerURL, + KolideServerURL: *flKolideServerURL, + LoggingInterval: *flLoggingInterval, MirrorServerURL: *flMirrorURL, NotaryPrefix: *flNotaryPrefix, - AutoupdateInterval: *flAutoupdateInterval, + NotaryServerURL: *flNotaryServerURL, + OsqueryFlags: flOsqueryFlags, + OsqueryVerbose: *flOsqueryVerbose, + OsquerydPath: osquerydPath, + RootDirectory: *flRootDirectory, + RootPEM: *flRootPEM, + Transport: *flTransport, UpdateChannel: updateChannel, } return opts, nil @@ -250,6 +252,7 @@ func developerUsage(flagset *flag.FlagSet) { fmt.Fprintf(os.Stderr, "\n") printOpt("debug") printOpt("osquery_verbose") + printOpt("debug_log_file") fmt.Fprintf(os.Stderr, "\n") printOpt("insecure") printOpt("insecure_transport") diff --git a/cmd/launcher/svc_windows.go b/cmd/launcher/svc_windows.go index 731e3cd21..5a205d0a8 100644 --- a/cmd/launcher/svc_windows.go +++ b/cmd/launcher/svc_windows.go @@ -11,10 +11,12 @@ import ( "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" "github.com/kolide/kit/logutil" + "github.com/kolide/kit/version" "github.com/kolide/launcher/pkg/autoupdate" "github.com/kolide/launcher/pkg/contexts/ctxlog" "github.com/kolide/launcher/pkg/launcher" "github.com/kolide/launcher/pkg/log/eventlog" + "github.com/kolide/launcher/pkg/log/teelogger" "github.com/pkg/errors" "golang.org/x/sys/windows/svc" "golang.org/x/sys/windows/svc/debug" @@ -33,14 +35,35 @@ func runWindowsSvc(args []string) error { defer eventLogWriter.Close() logger := eventlog.New(eventLogWriter) - level.Debug(logger).Log("msg", "service start requested") + logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + + level.Debug(logger).Log( + "msg", "service start requested", + "version", version.Version().Version, + ) opts, err := parseOptions(os.Args[2:]) if err != nil { - level.Info(logger).Log("err", err) + level.Info(logger).Log("msg", "Error parsing options", "err", err) os.Exit(1) } + if opts.DebugLogFile != "" { + logMirror, err := os.OpenFile(opts.DebugLogFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + level.Info(logger).Log("msg", "Failed to create file logger", "err", err) + os.Exit(2) + } + defer logMirror.Close() + + fileLogger := log.NewJSONLogger(log.NewSyncWriter(logMirror)) + fileLogger = log.With(fileLogger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) + + logger = teelogger.New(logger, fileLogger) + + level.Info(logger).Log("msg", "Mirroring logs to file", "file", logMirror.Name()) + } + // Now that we've parsed the options, let's set a filter on our logger if opts.Debug { logger = level.NewFilter(logger, level.AllowDebug()) @@ -62,15 +85,38 @@ func runWindowsSvc(args []string) error { ) }() - run := svc.Run + level.Info(logger).Log( + "msg", "launching service", + "version", version.Version().Version, + ) + + // Log panics from the windows service + defer func() { + if r := recover(); r != nil { + level.Info(logger).Log( + "msg", "panic occurred", + "err", err, + ) + time.Sleep(time.Second) + } + }() - if err := run(serviceName, &winSvc{logger: logger, opts: opts}); err != nil { + if err := svc.Run(serviceName, &winSvc{logger: logger, 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 - level.Info(logger).Log("msg", "svc run", "err", err) + level.Info(logger).Log( + "msg", "Error in service run", + "err", err, + "version", version.Version().Version, + ) + time.Sleep(time.Second) return err } + + level.Debug(logger).Log("msg", "Service exited", "version", version.Version().Version) + time.Sleep(time.Second) + return nil } @@ -103,7 +149,7 @@ type winSvc struct { func (w *winSvc) Execute(args []string, r <-chan svc.ChangeRequest, changes chan<- svc.Status) (ssec bool, errno uint32) { const cmdsAccepted = svc.AcceptStop | svc.AcceptShutdown changes <- svc.Status{State: svc.StartPending} - level.Info(w.logger).Log("msg", "windows service starting") + level.Debug(w.logger).Log("msg", "windows service starting") changes <- svc.Status{State: svc.Running, Accepts: cmdsAccepted} ctx, cancel := context.WithCancel(context.Background()) @@ -139,6 +185,7 @@ func (w *winSvc) Execute(args []string, r <-chan svc.ChangeRequest, changes chan time.Sleep(100 * time.Millisecond) changes <- c.CurrentStatus case svc.Stop, svc.Shutdown: + level.Info(w.logger).Log("msg", "shutdown request received") changes <- svc.Status{State: svc.StopPending} cancel() time.Sleep(100 * time.Millisecond) diff --git a/go.mod b/go.mod index d8772f2bc..f8c50a6b3 100644 --- a/go.mod +++ b/go.mod @@ -73,7 +73,7 @@ require ( golang.org/x/image v0.0.0-20190227222117-0694c2d4d067 golang.org/x/net v0.0.0-20190827160401-ba9fcec4b297 golang.org/x/sync v0.0.0-20190423024810-112230192c58 - golang.org/x/sys v0.0.0-20190904154756-749cb33beabd + golang.org/x/sys v0.0.0-20200803150936-fd5f0c170ac3 golang.org/x/time v0.0.0-20190308202827-9d24e82272b4 google.golang.org/grpc v1.23.0 gopkg.in/dancannon/gorethink.v3 v3.0.5 // indirect diff --git a/go.sum b/go.sum index 289b1fda5..918a9e707 100644 --- a/go.sum +++ b/go.sum @@ -305,6 +305,8 @@ golang.org/x/sys v0.0.0-20190606165138-5da285871e9c/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20190624142023-c5567b49c5d0/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190904154756-749cb33beabd h1:DBH9mDw0zluJT/R+nGuV3jWFWLFaHyYZWD4tOT+cjn0= golang.org/x/sys v0.0.0-20190904154756-749cb33beabd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20200803150936-fd5f0c170ac3 h1:Q8sHd8ZmZZguDQWkUYcD4pIRG5dG+euDEmNyknTRbGs= +golang.org/x/sys v0.0.0-20200803150936-fd5f0c170ac3/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.1-0.20180807135948-17ff2d5776d2/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= diff --git a/pkg/launcher/options.go b/pkg/launcher/options.go index 7ea83b00b..a73999003 100644 --- a/pkg/launcher/options.go +++ b/pkg/launcher/options.go @@ -60,6 +60,8 @@ type Options struct { // Debug enables debug logging. Debug bool + // Optional file to mirror debug logs to + DebugLogFile string // OsqueryVerbose puts osquery into verbose mode OsqueryVerbose bool // OsqueryFlags defines additional flags to pass to osquery (possibly diff --git a/pkg/log/teelogger/teelogger.go b/pkg/log/teelogger/teelogger.go new file mode 100644 index 000000000..61d5dd01c --- /dev/null +++ b/pkg/log/teelogger/teelogger.go @@ -0,0 +1,31 @@ +// Package filetee provides a go-kit compatible log mirroring tool. +package teelogger + +import ( + "github.com/go-kit/kit/log" +) + +type teeLogger struct { + loggers []log.Logger +} + +func New(loggers ...log.Logger) log.Logger { + l := &teeLogger{ + loggers: loggers, + } + + return l +} + +// Log will log to each logger. If any of them error, it will return a +// random error. +func (l *teeLogger) Log(keyvals ...interface{}) error { + var randomErr error + for _, logger := range l.loggers { + if err := logger.Log(keyvals...); err != nil { + randomErr = err + } + } + + return randomErr +}