From 78515da285215548bfd62b48e8c695bc6258e05c Mon Sep 17 00:00:00 2001 From: Alex Goodman Date: Sat, 1 Aug 2020 11:56:38 -0400 Subject: [PATCH] replace zap logger with logrus (#116) --- cmd/cmd.go | 8 +- cmd/root.go | 4 +- go.mod | 2 + go.sum | 3 + internal/config/config.go | 21 ++--- internal/logger/logrus.go | 115 ++++++++++++++++++++++++ internal/logger/zap.go | 141 ------------------------------ internal/ui/etui/ephemeral_tui.go | 16 ++++ syft/lib.go | 7 +- 9 files changed, 158 insertions(+), 159 deletions(-) create mode 100644 internal/logger/logrus.go delete mode 100644 internal/logger/zap.go diff --git a/cmd/cmd.go b/cmd/cmd.go index 274706dd5f4..49adba1c890 100644 --- a/cmd/cmd.go +++ b/cmd/cmd.go @@ -90,7 +90,7 @@ func initAppConfig() { } func initLogging() { - cfg := logger.LogConfig{ + cfg := logger.LogrusConfig{ EnableConsole: (appConfig.Log.FileLocation == "" || appConfig.CliOptions.Verbosity > 0) && !appConfig.Quiet, EnableFile: appConfig.Log.FileLocation != "", Level: appConfig.Log.LevelOpt, @@ -98,9 +98,11 @@ func initLogging() { FileLocation: appConfig.Log.FileLocation, } - logWrapper := logger.NewZapLogger(cfg) + logWrapper := logger.NewLogrusLogger(cfg) syft.SetLogger(logWrapper) - stereoscope.SetLogger(logWrapper) + stereoscope.SetLogger(&logger.LogrusNestedLogger{ + Logger: logWrapper.Logger.WithField("from-lib", "steroscope"), + }) } func logAppConfig() { diff --git a/cmd/root.go b/cmd/root.go index d4bd4ebd579..8c92e1bd06b 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -49,14 +49,14 @@ func startWorker(userInput string) <-chan error { log.Errorf(err.Error()) } if isAvailable { - log.Infof("New version of %s is available: %s", internal.ApplicationName, newVersion) + log.Infof("new version of %s is available: %s", internal.ApplicationName, newVersion) bus.Publish(partybus.Event{ Type: event.AppUpdateAvailable, Value: newVersion, }) } else { - log.Debugf("No new %s update available", internal.ApplicationName) + log.Debugf("no new %s update available", internal.ApplicationName) } } diff --git a/go.mod b/go.mod index d5487cbf336..f7c6705c02e 100644 --- a/go.mod +++ b/go.mod @@ -19,12 +19,14 @@ require ( github.com/olekukonko/tablewriter v0.0.4 github.com/rogpeppe/go-internal v1.5.2 github.com/sergi/go-diff v1.1.0 + github.com/sirupsen/logrus v1.6.0 github.com/spf13/cobra v1.0.0 github.com/spf13/viper v1.7.0 github.com/wagoodman/go-partybus v0.0.0-20200526224238-eb215533f07d github.com/wagoodman/go-progress v0.0.0-20200731105512-1020f39e6240 github.com/wagoodman/go-rpmdb v0.0.0-20200719223757-ce54a4b0607b github.com/wagoodman/jotframe v0.0.0-20200730190914-3517092dd163 + github.com/x-cray/logrus-prefixed-formatter v0.5.2 go.uber.org/zap v1.15.0 golang.org/x/crypto v0.0.0-20200604202706-70a84ac30bf9 golang.org/x/sys v0.0.0-20200610111108-226ff32320da // indirect diff --git a/go.sum b/go.sum index a062afd6ad4..bc8876be47f 100644 --- a/go.sum +++ b/go.sum @@ -597,6 +597,7 @@ github.com/mattn/go-zglob v0.0.1/go.mod h1:9fxibJccNxU2cnpIKLRRFA7zX7qhkJIQWBb44 github.com/mattn/goveralls v0.0.2/go.mod h1:8d1ZMHsd7fW6IRPKQh46F2WRpyib5/X4FOpevwGNQEw= github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0= github.com/maxbrunsfeld/counterfeiter/v6 v6.2.2/go.mod h1:eD9eIE7cdwcMi9rYluz88Jz2VyhSmden33/aXg4oVIY= +github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b h1:j7+1HpAFS1zy5+Q4qx1fWh90gTKwiN4QCGoY9TWyyO4= github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b/go.mod h1:01TrycV0kFyexm33Z7vhZRXopbI8J3TDReVlkTgMUxE= github.com/miekg/dns v1.0.14/go.mod h1:W1PPwlIAgtquWBMBEV9nkV9Cazfe8ScdGz/Lj7v3Nrg= github.com/mitchellh/cli v1.0.0/go.mod h1:hNIlj7HEI86fIcpObd7a0FcrxTWetlwJDGcceTlRvqc= @@ -829,6 +830,8 @@ github.com/wagoodman/go-rpmdb v0.0.0-20200719223757-ce54a4b0607b h1:elYGLFZPymeT github.com/wagoodman/go-rpmdb v0.0.0-20200719223757-ce54a4b0607b/go.mod h1:MjoIZzKmbYfcpbC6ARWMcHijAjtLBViDaHcayXKWQWI= github.com/wagoodman/jotframe v0.0.0-20200730190914-3517092dd163 h1:qoZwR+bHbFFNirY4Yt7lqbOXnFAMnlFfR89w0TXwjrc= github.com/wagoodman/jotframe v0.0.0-20200730190914-3517092dd163/go.mod h1:DzXZ1wfRedNhC3KQTick8Gf3CEPMFHsP5k4R/ldjKtw= +github.com/x-cray/logrus-prefixed-formatter v0.5.2 h1:00txxvfBM9muc0jiLIEAkAcIMJzfthRT6usrui8uGmg= +github.com/x-cray/logrus-prefixed-formatter v0.5.2/go.mod h1:2duySbKsL6M18s5GU7VPsoEPHyzalCE06qoARUCeBBE= github.com/xanzy/go-gitlab v0.31.0/go.mod h1:sPLojNBn68fMUWSxIJtdVVIP8uSBYqesTfDUseX11Ug= github.com/xanzy/go-gitlab v0.32.0 h1:tBm+OXv1t+KBsqlXkSDFz+YUjRM0GFsjpOWYOod3Ebs= github.com/xanzy/go-gitlab v0.32.0/go.mod h1:sPLojNBn68fMUWSxIJtdVVIP8uSBYqesTfDUseX11Ug= diff --git a/internal/config/config.go b/internal/config/config.go index dd8a8c57d51..9ab861a433e 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -10,8 +10,8 @@ import ( "github.com/anchore/syft/syft/presenter" "github.com/anchore/syft/syft/scope" "github.com/mitchellh/go-homedir" + "github.com/sirupsen/logrus" "github.com/spf13/viper" - "go.uber.org/zap/zapcore" ) type CliOnlyOptions struct { @@ -33,7 +33,7 @@ type Application struct { type Logging struct { Structured bool `mapstructure:"structured"` - LevelOpt zapcore.Level + LevelOpt logrus.Level Level string `mapstructure:"level"` FileLocation string `mapstructure:"file"` } @@ -88,29 +88,30 @@ func (cfg *Application) Build() error { if cfg.Quiet { // TODO: this is bad: quiet option trumps all other logging options - // we should be able to quiet the consol logging and leave file logging alone... + // we should be able to quiet the console logging and leave file logging alone... // ... this will be an enhancement for later - cfg.Log.LevelOpt = zapcore.PanicLevel + cfg.Log.LevelOpt = logrus.PanicLevel } else { if cfg.Log.Level != "" { if cfg.CliOptions.Verbosity > 0 { return fmt.Errorf("cannot explicitly set log level (cfg file or env var) and use -v flag together") } - // set the log level explicitly - err := cfg.Log.LevelOpt.Set(cfg.Log.Level) + lvl, err := logrus.ParseLevel(strings.ToLower(cfg.Log.Level)) if err != nil { - return fmt.Errorf("bad log level value '%s': %+v", cfg.Log.Level, err) + return fmt.Errorf("bad log level configured (%q): %w", cfg.Log.Level, err) } + // set the log level explicitly + cfg.Log.LevelOpt = lvl } else { // set the log level implicitly switch v := cfg.CliOptions.Verbosity; { case v == 1: - cfg.Log.LevelOpt = zapcore.InfoLevel + cfg.Log.LevelOpt = logrus.InfoLevel case v >= 2: - cfg.Log.LevelOpt = zapcore.DebugLevel + cfg.Log.LevelOpt = logrus.DebugLevel default: - cfg.Log.LevelOpt = zapcore.ErrorLevel + cfg.Log.LevelOpt = logrus.ErrorLevel } } } diff --git a/internal/logger/logrus.go b/internal/logger/logrus.go new file mode 100644 index 00000000000..bfe105a3a9e --- /dev/null +++ b/internal/logger/logrus.go @@ -0,0 +1,115 @@ +package logger + +import ( + "fmt" + "io" + "io/ioutil" + "os" + + "github.com/sirupsen/logrus" + prefixed "github.com/x-cray/logrus-prefixed-formatter" +) + +type LogrusConfig struct { + EnableConsole bool + EnableFile bool + Structured bool + Level logrus.Level + FileLocation string +} + +type LogrusLogger struct { + Config LogrusConfig + Logger *logrus.Logger +} + +type LogrusNestedLogger struct { + Logger *logrus.Entry +} + +func NewLogrusLogger(cfg LogrusConfig) *LogrusLogger { + appLogger := logrus.New() + + var output io.Writer + switch { + case cfg.EnableConsole && cfg.EnableFile: + logFile, err := os.OpenFile(cfg.FileLocation, os.O_WRONLY|os.O_CREATE, 0755) + if err != nil { + panic(fmt.Errorf("unable to setup log file: %w", err)) + } + output = io.MultiWriter(os.Stderr, logFile) + case cfg.EnableConsole: + output = os.Stderr + case cfg.EnableFile: + logFile, err := os.OpenFile(cfg.FileLocation, os.O_WRONLY|os.O_CREATE, 0755) + if err != nil { + panic(fmt.Errorf("unable to setup log file: %w", err)) + } + output = logFile + default: + output = ioutil.Discard + } + + appLogger.SetOutput(output) + appLogger.SetLevel(cfg.Level) + + if cfg.Structured { + appLogger.SetFormatter(&logrus.JSONFormatter{ + TimestampFormat: "2006-01-02 15:04:05", + DisableTimestamp: false, + DisableHTMLEscape: false, + PrettyPrint: false, + }) + } else { + appLogger.SetFormatter(&prefixed.TextFormatter{ + TimestampFormat: "2006-01-02 15:04:05", + ForceColors: true, + ForceFormatting: true, + }) + } + + return &LogrusLogger{ + Config: cfg, + Logger: appLogger, + } +} + +func (l *LogrusLogger) Debugf(format string, args ...interface{}) { + l.Logger.Debugf(format, args...) +} + +func (l *LogrusLogger) Infof(format string, args ...interface{}) { + l.Logger.Infof(format, args...) +} + +func (l *LogrusLogger) Debug(args ...interface{}) { + l.Logger.Debug(args...) +} + +func (l *LogrusLogger) Info(args ...interface{}) { + l.Logger.Info(args...) +} + +func (l *LogrusLogger) Errorf(format string, args ...interface{}) { + l.Logger.Errorf(format, args...) +} + +func (l *LogrusNestedLogger) Debugf(format string, args ...interface{}) { + l.Logger.Debugf(format, args...) +} + +func (l *LogrusNestedLogger) Infof(format string, args ...interface{}) { + l.Logger.Infof(format, args...) +} + +func (l *LogrusNestedLogger) Debug(args ...interface{}) { + l.Logger.Debug(args...) +} + +func (l *LogrusNestedLogger) Info(args ...interface{}) { + l.Logger.Info(args...) +} + +func (l *LogrusNestedLogger) Errorf(format string, args ...interface{}) { + l.Logger.Errorf(format, args...) +} diff --git a/internal/logger/zap.go b/internal/logger/zap.go deleted file mode 100644 index 272932f5c51..00000000000 --- a/internal/logger/zap.go +++ /dev/null @@ -1,141 +0,0 @@ -package logger - -import ( - "os" - - "github.com/anchore/syft/internal/format" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" -) - -var levelToColor = map[zapcore.Level]format.Color{ - zapcore.DebugLevel: format.Magenta, - zapcore.InfoLevel: format.Blue, - zapcore.WarnLevel: format.Yellow, - zapcore.ErrorLevel: format.Red, - zapcore.DPanicLevel: format.Red, - zapcore.PanicLevel: format.Red, - zapcore.FatalLevel: format.Red, -} - -type LogConfig struct { - EnableConsole bool - EnableFile bool - Structured bool - Level zapcore.Level - FileLocation string -} - -type ZapLogger struct { - Config LogConfig - Logger *zap.SugaredLogger -} - -// TODO: Consider a human readable text encoder for better field handeling: -// - https://github.com/uber-go/zap/issues/570 -// - https://github.com/uber-go/zap/pull/123 -// - TextEncoder w/ old interface: https://github.com/uber-go/zap/blob/6c2107996402d47d559199b78e1c44747fe732f9/text_encoder.go -// - New interface example: https://github.com/uber-go/zap/blob/c2633d6de2d6e1170ad8f150660e3cf5310067c8/zapcore/json_encoder.go -// - Register the encoder: https://github.com/uber-go/zap/blob/v1.15.0/encoder.go -func NewZapLogger(config LogConfig) *ZapLogger { - appLogger := ZapLogger{ - Config: config, - } - cores := []zapcore.Core{} - - if config.EnableConsole { - // note: the report should go to stdout, all logs should go to stderr - writer := zapcore.Lock(os.Stderr) - core := zapcore.NewCore(appLogger.getConsoleEncoder(config), writer, config.Level) - cores = append(cores, core) - } - - if config.EnableFile { - writer := zapcore.AddSync(appLogger.logFileWriter(config.FileLocation)) - core := zapcore.NewCore(appLogger.fileEncoder(config), writer, config.Level) - cores = append(cores, core) - } - - combinedCore := zapcore.NewTee(cores...) - - // AddCallerSkip skips 2 number of callers, this is important else the file that gets - // logged will always be the wrapped file (In our case logger.go) - appLogger.Logger = zap.New( - combinedCore, - zap.AddCallerSkip(2), - zap.AddCaller(), - ).Sugar() - - return &appLogger -} - -func (l *ZapLogger) GetNamedLogger(name string) *ZapLogger { - return &ZapLogger{ - Logger: l.Logger.Named(name), - } -} - -func (l *ZapLogger) getConsoleEncoder(config LogConfig) zapcore.Encoder { - encoderConfig := zap.NewProductionEncoderConfig() - if config.Structured { - encoderConfig.EncodeName = zapcore.FullNameEncoder - encoderConfig.EncodeCaller = zapcore.ShortCallerEncoder - return zapcore.NewJSONEncoder(encoderConfig) - } - encoderConfig.EncodeTime = nil - encoderConfig.EncodeCaller = nil - encoderConfig.EncodeLevel = l.consoleLevelEncoder - encoderConfig.EncodeName = l.nameEncoder - return zapcore.NewConsoleEncoder(encoderConfig) -} - -func (l *ZapLogger) nameEncoder(loggerName string, enc zapcore.PrimitiveArrayEncoder) { - enc.AppendString("[" + loggerName + "]") -} - -func (l *ZapLogger) consoleLevelEncoder(level zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { - if level != zapcore.InfoLevel || l.Config.Level == zapcore.DebugLevel { - color, ok := levelToColor[level] - if !ok { - enc.AppendString("[" + level.CapitalString() + "]") - } else { - enc.AppendString("[" + color.Format(level.CapitalString()) + "]") - } - } -} - -func (l *ZapLogger) fileEncoder(config LogConfig) zapcore.Encoder { - encoderConfig := zap.NewProductionEncoderConfig() - encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder - encoderConfig.EncodeName = zapcore.FullNameEncoder - encoderConfig.EncodeCaller = zapcore.FullCallerEncoder - if config.Structured { - return zapcore.NewJSONEncoder(encoderConfig) - } - return zapcore.NewConsoleEncoder(encoderConfig) -} - -func (l *ZapLogger) logFileWriter(location string) zapcore.WriteSyncer { - file, _ := os.Create(location) - return zapcore.AddSync(file) -} - -func (l *ZapLogger) Debugf(format string, args ...interface{}) { - l.Logger.Debugf(format, args...) -} - -func (l *ZapLogger) Infof(format string, args ...interface{}) { - l.Logger.Infof(format, args...) -} - -func (l *ZapLogger) Debug(args ...interface{}) { - l.Logger.Debug(args...) -} - -func (l *ZapLogger) Info(args ...interface{}) { - l.Logger.Info(args...) -} - -func (l *ZapLogger) Errorf(format string, args ...interface{}) { - l.Logger.Errorf(format, args...) -} diff --git a/internal/ui/etui/ephemeral_tui.go b/internal/ui/etui/ephemeral_tui.go index 2cc3cf8fa45..afb00c68882 100644 --- a/internal/ui/etui/ephemeral_tui.go +++ b/internal/ui/etui/ephemeral_tui.go @@ -1,11 +1,14 @@ package etui import ( + "bytes" "context" "fmt" "os" "sync" + "github.com/anchore/syft/internal/logger" + "github.com/anchore/syft/internal/ui/common" "github.com/anchore/syft/ui" @@ -36,6 +39,13 @@ func setupScreen(output *os.File) *frame.Frame { func OutputToEphemeralTUI(workerErrs <-chan error, subscription *partybus.Subscription) error { output := os.Stderr + // prep the logger to not clobber the screen from now on (logrus only) + logBuffer := bytes.NewBufferString("") + logWrapper, ok := log.Log.(*logger.LogrusLogger) + if ok { + logWrapper.Logger.SetOutput(logBuffer) + } + // hide cursor _, _ = fmt.Fprint(output, "\x1b[?25l") // show cursor @@ -50,6 +60,8 @@ func OutputToEphemeralTUI(workerErrs <-chan error, subscription *partybus.Subscr if !isClosed { fr.Close() frame.Close() + // flush any errors to the screen before the report + fmt.Fprint(output, logBuffer.String()) } }() @@ -86,9 +98,13 @@ eventLoop: // finish before discontinuing dynamic content and showing the final report wg.Wait() fr.Close() + // TODO: there is a race condition within frame.Close() that sometimes leads to an extra blank line being output frame.Close() isClosed = true + // flush any errors to the screen before the report + fmt.Fprint(output, logBuffer.String()) + if err := common.CatalogerFinishedHandler(e); err != nil { log.Errorf("unable to show %s event: %+v", e.Type, err) } diff --git a/syft/lib.go b/syft/lib.go index 271b7b17555..adbd48e4b28 100644 --- a/syft/lib.go +++ b/syft/lib.go @@ -12,6 +12,7 @@ import ( ) func Catalog(userInput string, scoptOpt scope.Option) (*pkg.Catalog, *scope.Scope, *distro.Distro, error) { + log.Info("cataloging image") s, cleanup, err := scope.NewScope(userInput, scoptOpt) defer cleanup() if err != nil { @@ -31,15 +32,15 @@ func Catalog(userInput string, scoptOpt scope.Option) (*pkg.Catalog, *scope.Scop func IdentifyDistro(s scope.Scope) distro.Distro { d := distro.Identify(s) if d.Type != distro.UnknownDistroType { - log.Infof("Identified Distro: %s", d.String()) + log.Infof("identified distro: %s", d.String()) } else { - log.Info("Could not identify distro") + log.Info("could not identify distro") } return d } func CatalogFromScope(s scope.Scope) (*pkg.Catalog, error) { - log.Info("Building the Catalog") + log.Info("building the catalog") return cataloger.Catalog(s) }