Refactor Logging using Zerolog

client/flags/flags.go

@@ -65,6 +65,10 @@ const (
 	FlagCountTotal       = "count-total"
 	FlagTimeoutHeight    = "timeout-height"
 	FlagKeyAlgorithm     = "algo"
+
+	// Tendermint logging flags
+	FlagLogLevel  = "log_level"
+	FlagLogFormat = "log_format"
 )
 
 // LineBreak can be included in a command list to provide a blank line

contrib/images/simd-env/Dockerfile

@@ -12,7 +12,7 @@ VOLUME [ /simd ]
 WORKDIR /simd
 EXPOSE 26656 26657
 ENTRYPOINT ["/usr/bin/wrapper.sh"]
-CMD ["start"]
+CMD ["start", "--log_format", "plain"]
 STOPSIGNAL SIGTERM
 
 COPY wrapper.sh /usr/bin/wrapper.sh

go.mod

@@ -35,6 +35,7 @@ require (
 	github.com/prometheus/common v0.15.0
 	github.com/rakyll/statik v0.1.7
 	github.com/regen-network/cosmos-proto v0.3.0
+	github.com/rs/zerolog v1.20.0
 	github.com/spf13/afero v1.2.2 // indirect
 	github.com/spf13/cast v1.3.1
 	github.com/spf13/cobra v1.1.1

go.sum

@@ -481,6 +481,9 @@ github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6L
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
 github.com/rs/cors v1.7.0 h1:+88SsELBHx5r+hZ8TCkggzSstaWNbDvThkVK8H6f9ik=
 github.com/rs/cors v1.7.0/go.mod h1:gFx+x8UowdsKA9AchylcLynDq+nNFfI8FkUZdN/jGCU=
+github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ=
+github.com/rs/zerolog v1.20.0 h1:38k9hgtUBdxFwE34yS8rTHmHBa4eN16E4DJlv177LNs=
+github.com/rs/zerolog v1.20.0/go.mod h1:IzD0RJ65iWH0w97OQQebJEvTZYvsCUm9WVLWBQrJRjo=
 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=
@@ -726,6 +729,7 @@ golang.org/x/tools v0.0.0-20190606124116-d0a3d012864b/go.mod h1:/rFqwRUd4F7ZHNgw
 golang.org/x/tools v0.0.0-20190621195816-6e04913cbbac/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
 golang.org/x/tools v0.0.0-20190628153133-6cdbf07be9d0/go.mod h1:/rFqwRUd4F7ZHNgwSSTFct+R/Kf4OFW1sUzUTQQTgfc=
 golang.org/x/tools v0.0.0-20190816200558-6889da9d5479/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.0.0-20190828213141-aed303cbaa74/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20190911174233-4f2ddba30aff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=

server/logger.go

@@ -0,0 +1,55 @@
+package server
+
+import (
+	"github.com/rs/zerolog"
+	tmlog "github.com/tendermint/tendermint/libs/log"
+)
+
+var _ tmlog.Logger = (*ZeroLogWrapper)(nil)
+
+// ZeroLogWrapper provides a wrapper around a zerolog.Logger instance. It implements
+// Tendermint's Logger interface.
+type ZeroLogWrapper struct {
+	zerolog.Logger
+}
+
+// Info implements Tendermint's Logger interface and logs with level INFO. A set
+// of key/value tuples may be provided to add context to the log. The number of
+// tuples must be even and the key of the tuple must be a string.
+func (z ZeroLogWrapper) Info(msg string, keyVals ...interface{}) {
+	z.Logger.Info().Fields(getLogFields(keyVals...)).Msg(msg)
+}
+
+// Error implements Tendermint's Logger interface and logs with level ERR. A set
+// of key/value tuples may be provided to add context to the log. The number of
+// tuples must be even and the key of the tuple must be a string.
+func (z ZeroLogWrapper) Error(msg string, keyVals ...interface{}) {
+	z.Logger.Error().Fields(getLogFields(keyVals...)).Msg(msg)
+}
+
+// Debug implements Tendermint's Logger interface and logs with level DEBUG. A set
+// of key/value tuples may be provided to add context to the log. The number of
+// tuples must be even and the key of the tuple must be a string.
+func (z ZeroLogWrapper) Debug(msg string, keyVals ...interface{}) {
+	z.Logger.Debug().Fields(getLogFields(keyVals...)).Msg(msg)
+}
+
+// With returns a new wrapped logger with additional context provided by a set
+// of key/value tuples. The number of tuples must be even and the key of the
+// tuple must be a string.
+func (z ZeroLogWrapper) With(keyVals ...interface{}) tmlog.Logger {
+	return ZeroLogWrapper{z.Logger.With().Fields(getLogFields(keyVals...)).Logger()}
+}
+
+func getLogFields(keyVals ...interface{}) map[string]interface{} {
+	if len(keyVals)%2 != 0 {
+		return nil
+	}
+
+	fields := make(map[string]interface{})
+	for i := 0; i < len(keyVals); i += 2 {
+		fields[keyVals[i].(string)] = keyVals[i+1]
+	}
+
+	return fields
+}

server/util.go

@@ -14,12 +14,12 @@ import (
 	"syscall"
 	"time"
 
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 	tmcfg "github.com/tendermint/tendermint/config"
-	tmcli "github.com/tendermint/tendermint/libs/cli"
-	tmflags "github.com/tendermint/tendermint/libs/cli/flags"
-	"github.com/tendermint/tendermint/libs/log"
+	tmlog "github.com/tendermint/tendermint/libs/log"
 	dbm "github.com/tendermint/tm-db"
 
 	"github.com/cosmos/cosmos-sdk/client/flags"
@@ -39,7 +39,7 @@ const ServerContextKey = sdk.ContextKey("server.context")
 type Context struct {
 	Viper  *viper.Viper
 	Config *tmcfg.Config
-	Logger log.Logger
+	Logger tmlog.Logger
 }
 
 // ErrorCode contains the exit code for server exit.
@@ -52,10 +52,14 @@ func (e ErrorCode) Error() string {
 }
 
 func NewDefaultContext() *Context {
-	return NewContext(viper.New(), tmcfg.DefaultConfig(), log.NewTMLogger(log.NewSyncWriter(os.Stdout)))
+	return NewContext(
+		viper.New(),
+		tmcfg.DefaultConfig(),
+		ZeroLogWrapper{log.Logger},
+	)
 }
 
-func NewContext(v *viper.Viper, config *tmcfg.Config, logger log.Logger) *Context {
+func NewContext(v *viper.Viper, config *tmcfg.Config, logger tmlog.Logger) *Context {
 	return &Context{v, config, logger}
 }
 
@@ -86,27 +90,29 @@ func InterceptConfigsPreRunHandler(cmd *cobra.Command) error {
 	serverCtx.Viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_", "-", "_"))
 	serverCtx.Viper.AutomaticEnv()
 
-	// Intercept configuration files, using both Viper instances separately
+	// intercept configuration files, using both Viper instances separately
 	config, err := interceptConfigs(serverCtx.Viper)
 	if err != nil {
 		return err
 	}
-	// Return value is a tendermint configuration object
+
+	// return value is a tendermint configuration object
 	serverCtx.Config = config
 
-	logger := log.NewTMLogger(log.NewSyncWriter(os.Stdout))
-	logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, tmcfg.DefaultLogLevel())
-	if err != nil {
-		return err
+	var logWriter io.Writer
+	if strings.ToLower(serverCtx.Viper.GetString(flags.FlagLogFormat)) == tmcfg.LogFormatPlain {
+		logWriter = zerolog.ConsoleWriter{Out: os.Stderr}
+	} else {
+		logWriter = os.Stderr
 	}
 
-	// Check if the tendermint flag for trace logging is set
-	// if it is then setup a tracing logger in this app as well
-	if serverCtx.Viper.GetBool(tmcli.TraceFlag) {
-		logger = log.NewTracingLogger(logger)
+	logLvlStr := serverCtx.Viper.GetString(flags.FlagLogLevel)
+	logLvl, err := zerolog.ParseLevel(logLvlStr)
+	if err != nil {
+		return fmt.Errorf("failed to parse log level (%s): %w", logLvlStr, err)
 	}
 
-	serverCtx.Logger = logger.With("module", "main")
+	serverCtx.Logger = ZeroLogWrapper{zerolog.New(logWriter).Level(logLvl).With().Timestamp().Logger()}
 
 	return SetCmdServerContext(cmd, serverCtx)
 }

simapp/simd/cmd/root.go

@@ -6,8 +6,10 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/rs/zerolog"
 	"github.com/spf13/cast"
 	"github.com/spf13/cobra"
+	tmcfg "github.com/tendermint/tendermint/config"
 	tmcli "github.com/tendermint/tendermint/libs/cli"
 	"github.com/tendermint/tendermint/libs/log"
 	dbm "github.com/tendermint/tm-db"
@@ -79,7 +81,8 @@ func Execute(rootCmd *cobra.Command) error {
 	ctx = context.WithValue(ctx, client.ClientContextKey, &client.Context{})
 	ctx = context.WithValue(ctx, server.ServerContextKey, srvCtx)
 
-	rootCmd.PersistentFlags().String("log_level", srvCtx.Config.LogLevel, "The logging level in the format of <module>:<level>,...")
+	rootCmd.PersistentFlags().String(flags.FlagLogLevel, zerolog.InfoLevel.String(), "The logging level (trace|debug|info|warn|error|fatal|panic)")
+	rootCmd.PersistentFlags().String(flags.FlagLogFormat, tmcfg.LogFormatJSON, "The logging format (json|plain)")
 
 	executor := tmcli.PrepareBaseCmd(rootCmd, "", simapp.DefaultNodeHome)
 	return executor.ExecuteContext(ctx)

x/bank/keeper/keeper.go

@@ -341,7 +341,7 @@ func (k BaseKeeper) MintCoins(ctx sdk.Context, moduleName string, amt sdk.Coins)
 	k.SetSupply(ctx, supply)
 
 	logger := k.Logger(ctx)
-	logger.Info(fmt.Sprintf("minted %s from %s module account", amt.String(), moduleName))
+	logger.Info("minted coins from module account", "amount", amt.String(), "from", moduleName)
 
 	return nil
 }

x/bank/keeper/view.go

@@ -49,7 +49,7 @@ func NewBaseViewKeeper(cdc codec.BinaryMarshaler, storeKey sdk.StoreKey, ak type
 
 // Logger returns a module-specific logger.
 func (k BaseViewKeeper) Logger(ctx sdk.Context) log.Logger {
-	return ctx.Logger().With("module", fmt.Sprintf("x/%s", types.ModuleName))
+	return ctx.Logger().With("module", "x/"+types.ModuleName)
 }
 
 // HasBalance returns whether or not an account has at least amt balance.