replace zap logger with logrus (#116)

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() {

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

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

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=

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
+			lvl, err := logrus.ParseLevel(strings.ToLower(cfg.Log.Level))
-			err := cfg.Log.LevelOpt.Set(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
 			}
 		}
 	}

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

internal/logger/zap.go

@@ -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...)
-}

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

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