Additional error handling (and optional debug file logging) (#639)

Adds several additional logging capabilities. Panic is now caught, and logged. A handful of extra startup log lines have been added.

Adds the capability to mirror debug to a file. This greatly helps when debugging on windows, as extracting structed json from a file is simpler than extracting from the event log. This is something of an early preview -- I'd rather enable this by default, we until we have a log rotation ability, it won't work.

Lastly, this upgrades the go svc version

cmd/launcher/main.go

@@ -7,14 +7,17 @@ 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"
 	"github.com/kolide/kit/version"
 	"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 {

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")

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)

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

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=

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

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
+}