feat(log): wire logger filtering

go.mod

@@ -8,7 +8,7 @@ require (
 	cosmossdk.io/core v0.6.1
 	cosmossdk.io/depinject v1.0.0-alpha.3
 	cosmossdk.io/errors v1.0.0-beta.7
-	cosmossdk.io/log v0.1.0
+	cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d
 	cosmossdk.io/math v1.0.0
 	cosmossdk.io/store v0.1.0-alpha.1.0.20230328185921-37ba88872dbc
 	cosmossdk.io/x/tx v0.5.0

go.sum

@@ -45,8 +45,8 @@ cosmossdk.io/depinject v1.0.0-alpha.3 h1:6evFIgj//Y3w09bqOUOzEpFj5tsxBqdc5CfkO7z
 cosmossdk.io/depinject v1.0.0-alpha.3/go.mod h1:eRbcdQ7MRpIPEM5YUJh8k97nxHpYbc3sMUnEtt8HPWU=
 cosmossdk.io/errors v1.0.0-beta.7 h1:gypHW76pTQGVnHKo6QBkb4yFOJjC+sUGRc5Al3Odj1w=
 cosmossdk.io/errors v1.0.0-beta.7/go.mod h1:mz6FQMJRku4bY7aqS/Gwfcmr/ue91roMEKAmDUDpBfE=
-cosmossdk.io/log v0.1.0 h1:Vnexi+KzUCjmqq/m93teAxjt5biWFfZ5PI1imx2IJw8=
-cosmossdk.io/log v0.1.0/go.mod h1:p95Wq6mDY3SREMc4y7+QU9Uwy3nyvfpWGD1iSaFkVFs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d h1:vRbhjJNv2/GuzU9/PX61Nl/+uyy3gmd5DKoNkQpMzSs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d/go.mod h1:CwX9BLiBruZb7lzLlRr3R231d/fVPUXk8gAdV4LQap0=
 cosmossdk.io/math v1.0.0 h1:ro9w7eKx23om2tZz/VM2Pf+z2WAbGX1yDQQOJ6iGeJw=
 cosmossdk.io/math v1.0.0/go.mod h1:Ygz4wBHrgc7g0N+8+MrnTfS9LLn9aaTGa9hKopuym5k=
 cosmossdk.io/store v0.1.0-alpha.1.0.20230328185921-37ba88872dbc h1:9piuA+NYmhe+SyMPtMoboLw/djgDbrI3dD5TG020Tnk=

log/CHANGELOG.md

@@ -31,8 +31,9 @@ Ref: https://keepachangelog.com/en/1.0.0/
 
 ## [Unreleased]
 
-<!-- ## [v1.0.0](https://github.com/cosmos/cosmos-sdk/releases/tag/log/v1.0.0) - 2023-0X-XX -->
-<!-- Wait for https://github.com/rs/zerolog/pull/527 to be merged -->
+## [v1.0.0](https://github.com/cosmos/cosmos-sdk/releases/tag/log/v1.0.0) - 2023-03-29
+
+* [#15601](https://github.com/cosmos/cosmos-sdk/pull/15601) Introduce logger options. These options allow to configure the logger with filters, different level and output format.
 
 ## [v0.1.0](https://github.com/cosmos/cosmos-sdk/releases/tag/log/v0.1.0) - 2023-03-13
 

log/level.go

@@ -8,12 +8,12 @@ import (
 	"github.com/rs/zerolog"
 )
 
+const defaultLogLevelKey = "*"
+
 // FilterFunc is a function that returns true if the log level is filtered for the given key
 // When the filter returns true, the log entry is discarded.
 type FilterFunc func(key, level string) bool
 
-const defaultLogLevelKey = "*"
-
 // ParseLogLevel parses complex log level
 // A comma-separated list of module:level pairs with an optional *:level pair
 // (* means all other modules).

log/logger.go

@@ -42,28 +42,35 @@ type zeroLogWrapper struct {
 	*zerolog.Logger
 }
 
-// NewNopLogger returns a new logger that does nothing.
-func NewNopLogger() Logger {
-	// The custom nopLogger is about 3x faster than a zeroLogWrapper with zerolog.Nop().
-	return nopLogger{}
-}
-
 // NewLogger returns a new logger that writes to the given destination.
 //
 // Typical usage from a main function is:
 // logger := log.NewLogger(os.Stderr)
 //
 // Stderr is the typical destination for logs,
 // so that any output from your application can still be piped to other processes.
-func NewLogger(dst io.Writer) Logger {
-	output := zerolog.ConsoleWriter{Out: dst, TimeFormat: time.Kitchen}
+func NewLogger(dst io.Writer, options ...Option) Logger {
+	logCfg := defaultConfig
+	for _, opt := range options {
+		opt(&logCfg)
+	}
+
+	output := dst
+	if !logCfg.OutputJSON {
+		output = zerolog.ConsoleWriter{Out: dst, TimeFormat: time.Kitchen}
+	}
+
+	if logCfg.Filter != nil {
+		output = NewFilterWriter(output, logCfg.Filter)
+	}
+
 	logger := zerolog.New(output).With().Timestamp().Logger()
-	return zeroLogWrapper{&logger}
-}
 
-// NewLoggerWithKV is shorthand for NewLogger(dst).With(key, value).
-func NewLoggerWithKV(dst io.Writer, key, value string) Logger {
-	return NewLogger(dst).With(key, value)
+	if logCfg.Level != zerolog.NoLevel {
+		logger = logger.Level(logCfg.Level)
+	}
+
+	return zeroLogWrapper{&logger}
 }
 
 // NewCustomLogger returns a new logger with the given zerolog logger.
@@ -101,33 +108,10 @@ func (l zeroLogWrapper) Impl() interface{} {
 	return l.Logger
 }
 
-// FilterKeys returns a new logger that filters out all key/value pairs that do not match the filter.
-// This functions assumes that the logger is a zerolog.Logger, which is the case for the logger returned by log.NewLogger().
-// NOTE: filtering has a performance impact on the logger.
-func FilterKeys(logger Logger, filter FilterFunc) Logger {
-	zl, ok := logger.Impl().(*zerolog.Logger)
-	if !ok {
-		panic("logger is not a zerolog.Logger")
-	}
-
-	filteredLogger := zl.Hook(zerolog.HookFunc(func(e *zerolog.Event, lvl zerolog.Level, _ string) {
-		// TODO(@julienrbrt) wait for https://github.com/rs/zerolog/pull/527 to be merged
-		// keys, err := e.GetKeys()
-		// if err != nil {
-		// 	panic(err)
-		// }
-
-		keys := []string{}
-
-		for _, key := range keys {
-			if filter(key, lvl.String()) {
-				e.Discard()
-				break
-			}
-		}
-	}))
-
-	return NewCustomLogger(filteredLogger)
+// NewNopLogger returns a new logger that does nothing.
+func NewNopLogger() Logger {
+	// The custom nopLogger is about 3x faster than a zeroLogWrapper with zerolog.Nop().
+	return nopLogger{}
 }
 
 // nopLogger is a Logger that does nothing when called.
@@ -139,4 +123,4 @@ func (nopLogger) Info(string, ...any)  {}
 func (nopLogger) Error(string, ...any) {}
 func (nopLogger) Debug(string, ...any) {}
 func (nopLogger) With(...any) Logger   { return nopLogger{} }
-func (nopLogger) Impl() any            { return nopLogger{} }
+func (nopLogger) Impl() any            { return zerolog.Nop() }

log/options.go

@@ -0,0 +1,40 @@
+package log
+
+import "github.com/rs/zerolog"
+
+// defaultConfig has all the options disabled.
+var defaultConfig = Config{
+	Level:      zerolog.NoLevel,
+	Filter:     nil,
+	OutputJSON: false,
+}
+
+// LoggerConfig defines configuration for the logger.
+type Config struct {
+	Level      zerolog.Level
+	Filter     FilterFunc
+	OutputJSON bool
+}
+
+type Option func(*Config)
+
+// FilterOption sets the filter for the Logger.
+func FilterOption(filter FilterFunc) Option {
+	return func(cfg *Config) {
+		cfg.Filter = filter
+	}
+}
+
+// LevelOption sets the level for the Logger.
+func LevelOption(level zerolog.Level) Option {
+	return func(cfg *Config) {
+		cfg.Level = level
+	}
+}
+
+// OutputJSONOption sets the output of the logger to JSON.
+func OutputJSONOption() Option {
+	return func(cfg *Config) {
+		cfg.OutputJSON = true
+	}
+}

log/writer.go

@@ -0,0 +1,45 @@
+package log
+
+import (
+	"encoding/json"
+	"fmt"
+	"io"
+)
+
+// NewFilterWriter returns a writer that filters out all key/value pairs that do not match the filter.
+// If the filter is nil, the writer will pass all events through.
+// The filter function is called with the module and level of the event.
+func NewFilterWriter(parent io.Writer, filter FilterFunc) io.Writer {
+	return &filterWriter{parent, filter}
+}
+
+type filterWriter struct {
+	parent io.Writer
+	filter FilterFunc
+}
+
+func (fw *filterWriter) Write(p []byte) (n int, err error) {
+	if fw.filter == nil {
+		return fw.parent.Write(p)
+	}
+
+	event := make(map[string]interface{})
+	if err := json.Unmarshal(p, &event); err != nil {
+		return 0, fmt.Errorf("failed to unmarshal event: %w", err)
+	}
+
+	level, ok := event["level"].(string)
+	if !ok {
+		return 0, fmt.Errorf("failed to get level from event")
+	}
+
+	// only filter module keys
+	module, ok := event[ModuleKey].(string)
+	if ok {
+		if fw.filter(module, level) {
+			return len(p), nil
+		}
+	}
+
+	return fw.parent.Write(p)
+}

log/writer_test.go

@@ -0,0 +1,27 @@
+package log_test
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"cosmossdk.io/log"
+	"gotest.tools/v3/assert"
+)
+
+func TestFilteredWriter(t *testing.T) {
+	checkBuf := new(bytes.Buffer)
+
+	level := "consensus:debug,mempool:debug,*:error"
+	filter, err := log.ParseLogLevel(level)
+	assert.NilError(t, err)
+
+	logger := log.NewLogger(checkBuf, log.FilterOption(filter))
+	logger.Debug("this log line should be displayed", log.ModuleKey, "consensus")
+	assert.Check(t, strings.Contains(checkBuf.String(), "this log line should be displayed"))
+	checkBuf.Reset()
+
+	logger.Debug("this log line should be filtered", log.ModuleKey, "server")
+	assert.Check(t, !strings.Contains(checkBuf.String(), "this log line should be filtered"))
+	checkBuf.Reset()
+}

server/util.go

@@ -169,37 +169,36 @@ func InterceptConfigsAndCreateContext(cmd *cobra.Command, customAppConfigTemplat
 // CreateSDKLogger creates a the default SDK logger.
 // It reads the log level and format from the server context.
 func CreateSDKLogger(ctx *Context, out io.Writer) (log.Logger, error) {
-	var logger log.Logger
+	var opts []log.Option
 	if ctx.Viper.GetString(flags.FlagLogFormat) == cmtcfg.LogFormatJSON {
-		zl := zerolog.New(out).With().Timestamp().Logger()
-		logger = log.NewCustomLogger(zl)
-	} else {
-		logger = log.NewLogger(out)
+		opts = append(opts, log.OutputJSONOption())
 	}
 
-	// set filter level or keys for the logger if any
+	// check and set filter level or keys for the logger if any
 	logLvlStr := ctx.Viper.GetString(flags.FlagLogLevel)
+	if logLvlStr == "" {
+		return log.NewLogger(out, opts...), nil
+	}
+
 	logLvl, err := zerolog.ParseLevel(logLvlStr)
 	if err != nil {
 		// If the log level is not a valid zerolog level, then we try to parse it as a key filter.
 		filterFunc, err := log.ParseLogLevel(logLvlStr)
 		if err != nil {
-			return nil, fmt.Errorf("failed to parse log level (%s): %w", logLvlStr, err)
+			return nil, err
 		}
 
-		logger = log.FilterKeys(logger, filterFunc)
-	} else {
-		zl := logger.Impl().(*zerolog.Logger)
+		opts = append(opts, log.FilterOption(filterFunc))
+
+	} else if ctx.Viper.GetBool(cmtcli.TraceFlag) {
 		// Check if the CometBFT flag for trace logging is set if it is then setup a tracing logger in this app as well.
 		// Note it overrides log level passed in `log_levels`.
-		if ctx.Viper.GetBool(cmtcli.TraceFlag) {
-			logger = log.NewCustomLogger(zl.Level(zerolog.TraceLevel))
-		} else {
-			logger = log.NewCustomLogger(zl.Level(logLvl))
-		}
+		opts = append(opts, log.LevelOption(zerolog.TraceLevel))
+	} else {
+		opts = append(opts, log.LevelOption(logLvl))
 	}
 
-	return logger, nil
+	return log.NewLogger(out, opts...), nil
 }
 
 // GetServerContextFromCmd returns a Context from a command or an empty Context

simapp/go.mod

@@ -7,7 +7,7 @@ require (
 	cosmossdk.io/client/v2 v2.0.0-20230309163709-87da587416ba
 	cosmossdk.io/core v0.6.1
 	cosmossdk.io/depinject v1.0.0-alpha.3
-	cosmossdk.io/log v0.1.0
+	cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d
 	cosmossdk.io/math v1.0.0
 	cosmossdk.io/store v0.1.0-alpha.1.0.20230328185921-37ba88872dbc
 	cosmossdk.io/tools/confix v0.0.0-20230120150717-4f6f6c00021f

simapp/go.sum

@@ -198,8 +198,8 @@ cosmossdk.io/depinject v1.0.0-alpha.3 h1:6evFIgj//Y3w09bqOUOzEpFj5tsxBqdc5CfkO7z
 cosmossdk.io/depinject v1.0.0-alpha.3/go.mod h1:eRbcdQ7MRpIPEM5YUJh8k97nxHpYbc3sMUnEtt8HPWU=
 cosmossdk.io/errors v1.0.0-beta.7 h1:gypHW76pTQGVnHKo6QBkb4yFOJjC+sUGRc5Al3Odj1w=
 cosmossdk.io/errors v1.0.0-beta.7/go.mod h1:mz6FQMJRku4bY7aqS/Gwfcmr/ue91roMEKAmDUDpBfE=
-cosmossdk.io/log v0.1.0 h1:Vnexi+KzUCjmqq/m93teAxjt5biWFfZ5PI1imx2IJw8=
-cosmossdk.io/log v0.1.0/go.mod h1:p95Wq6mDY3SREMc4y7+QU9Uwy3nyvfpWGD1iSaFkVFs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d h1:vRbhjJNv2/GuzU9/PX61Nl/+uyy3gmd5DKoNkQpMzSs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d/go.mod h1:CwX9BLiBruZb7lzLlRr3R231d/fVPUXk8gAdV4LQap0=
 cosmossdk.io/math v1.0.0 h1:ro9w7eKx23om2tZz/VM2Pf+z2WAbGX1yDQQOJ6iGeJw=
 cosmossdk.io/math v1.0.0/go.mod h1:Ygz4wBHrgc7g0N+8+MrnTfS9LLn9aaTGa9hKopuym5k=
 cosmossdk.io/x/tx v0.5.0 h1:01wPSoiYDHlfudV0fn867SBXI3uI/8tpatBgVVSnFzI=

tests/go.mod

@@ -6,7 +6,7 @@ require (
 	cosmossdk.io/api v0.3.2-0.20230313131911-55bf5d4efbe7
 	cosmossdk.io/depinject v1.0.0-alpha.3
 	cosmossdk.io/errors v1.0.0-beta.7
-	cosmossdk.io/log v0.1.0
+	cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d
 	cosmossdk.io/math v1.0.0
 	cosmossdk.io/simapp v0.0.0-20230309163709-87da587416ba
 	cosmossdk.io/store v0.1.0-alpha.1.0.20230328185921-37ba88872dbc

tests/go.sum

@@ -200,8 +200,8 @@ cosmossdk.io/depinject v1.0.0-alpha.3 h1:6evFIgj//Y3w09bqOUOzEpFj5tsxBqdc5CfkO7z
 cosmossdk.io/depinject v1.0.0-alpha.3/go.mod h1:eRbcdQ7MRpIPEM5YUJh8k97nxHpYbc3sMUnEtt8HPWU=
 cosmossdk.io/errors v1.0.0-beta.7 h1:gypHW76pTQGVnHKo6QBkb4yFOJjC+sUGRc5Al3Odj1w=
 cosmossdk.io/errors v1.0.0-beta.7/go.mod h1:mz6FQMJRku4bY7aqS/Gwfcmr/ue91roMEKAmDUDpBfE=
-cosmossdk.io/log v0.1.0 h1:Vnexi+KzUCjmqq/m93teAxjt5biWFfZ5PI1imx2IJw8=
-cosmossdk.io/log v0.1.0/go.mod h1:p95Wq6mDY3SREMc4y7+QU9Uwy3nyvfpWGD1iSaFkVFs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d h1:vRbhjJNv2/GuzU9/PX61Nl/+uyy3gmd5DKoNkQpMzSs=
+cosmossdk.io/log v0.1.1-0.20230329182155-367f0dc1194d/go.mod h1:CwX9BLiBruZb7lzLlRr3R231d/fVPUXk8gAdV4LQap0=
 cosmossdk.io/math v1.0.0 h1:ro9w7eKx23om2tZz/VM2Pf+z2WAbGX1yDQQOJ6iGeJw=
 cosmossdk.io/math v1.0.0/go.mod h1:Ygz4wBHrgc7g0N+8+MrnTfS9LLn9aaTGa9hKopuym5k=
 cosmossdk.io/x/tx v0.5.0 h1:01wPSoiYDHlfudV0fn867SBXI3uI/8tpatBgVVSnFzI=

tools/cosmovisor/cmd/cosmovisor/main.go

@@ -9,7 +9,7 @@ import (
 )
 
 func main() {
-	logger := log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "cosmovisor")
+	logger := log.NewLogger(os.Stdout).With(log.ModuleKey, "cosmovisor")
 	ctx := context.WithValue(context.Background(), log.ContextKey, logger)
 
 	if err := NewRootCmd().ExecuteContext(ctx); err != nil {

tools/cosmovisor/process_test.go

@@ -112,7 +112,7 @@ func (s *processTestSuite) TestLaunchProcessWithDownloads() {
 	require := s.Require()
 	home := copyTestData(s.T(), "download")
 	cfg := &cosmovisor.Config{Home: home, Name: "autod", AllowDownloadBinaries: true, PollInterval: 100, UnsafeSkipBackup: true}
-	logger := log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "cosmovisor")
+	logger := log.NewLogger(os.Stdout).With(log.ModuleKey, "cosmovisor")
 	upgradeFilename := cfg.UpgradeInfoFilePath()
 
 	// should run the genesis binary and produce expected output

tools/cosmovisor/upgrade_test.go

@@ -95,7 +95,7 @@ func (s *upgradeTestSuite) assertCurrentLink(cfg cosmovisor.Config, target strin
 func (s *upgradeTestSuite) TestUpgradeBinaryNoDownloadUrl() {
 	home := copyTestData(s.T(), "validate")
 	cfg := &cosmovisor.Config{Home: home, Name: "dummyd", AllowDownloadBinaries: true}
-	logger := log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "cosmovisor").Impl().(*zerolog.Logger)
+	logger := log.NewLogger(os.Stdout).With(log.ModuleKey, "cosmovisor").Impl().(*zerolog.Logger)
 
 	currentBin, err := cfg.CurrentBin()
 	s.Require().NoError(err)
@@ -128,7 +128,7 @@ func (s *upgradeTestSuite) TestUpgradeBinaryNoDownloadUrl() {
 }
 
 func (s *upgradeTestSuite) TestUpgradeBinary() {
-	logger := log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "cosmovisor").Impl().(*zerolog.Logger)
+	logger := log.NewLogger(os.Stdout).With(log.ModuleKey, "cosmovisor").Impl().(*zerolog.Logger)
 
 	cases := map[string]struct {
 		url         string

tools/rosetta/cmd/rosetta/main.go

@@ -11,7 +11,7 @@ import (
 
 func main() {
 	var (
-		logger            = log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "rosetta")
+		logger            = log.NewLogger(os.Stdout).With(log.ModuleKey, "rosetta")
 		interfaceRegistry = codectypes.NewInterfaceRegistry()
 		cdc               = codec.NewProtoCodec(interfaceRegistry)
 	)