From d21f58c638d54461404875efb8b72361b44c2d33 Mon Sep 17 00:00:00 2001 From: Julien Robert Date: Thu, 30 Mar 2023 11:48:38 +0200 Subject: [PATCH] feat(log): wire logger filtering (#15601) --- go.mod | 2 +- go.sum | 4 +- log/CHANGELOG.md | 5 +- log/level.go | 4 +- log/logger.go | 67 ++++++++++--------------- log/options.go | 42 ++++++++++++++++ log/writer.go | 41 +++++++++++++++ log/writer_test.go | 26 ++++++++++ server/util.go | 31 ++++++------ simapp/go.mod | 2 +- simapp/go.sum | 4 +- tests/go.mod | 2 +- tests/go.sum | 4 +- tools/cosmovisor/cmd/cosmovisor/main.go | 2 +- tools/cosmovisor/process_test.go | 2 +- tools/cosmovisor/upgrade_test.go | 4 +- tools/rosetta/cmd/rosetta/main.go | 2 +- tools/rosetta/lib/server/server.go | 2 +- 18 files changed, 170 insertions(+), 76 deletions(-) create mode 100644 log/options.go create mode 100644 log/writer.go create mode 100644 log/writer_test.go diff --git a/go.mod b/go.mod index ac3fcb9e7bae..946d03e25f5d 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index f3a9f2fcf56a..52eed1db3401 100644 --- a/go.sum +++ b/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= diff --git a/log/CHANGELOG.md b/log/CHANGELOG.md index c057371645ea..f393ecc080f9 100644 --- a/log/CHANGELOG.md +++ b/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-03-30 + +* [#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 diff --git a/log/level.go b/log/level.go index f65689d85a0e..105b4a10fa82 100644 --- a/log/level.go +++ b/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). diff --git a/log/logger.go b/log/logger.go index 8513fd4be2c6..da1552ef6a01 100644 --- a/log/logger.go +++ b/log/logger.go @@ -42,28 +42,36 @@ 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) +// +// 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 +109,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. diff --git a/log/options.go b/log/options.go new file mode 100644 index 000000000000..831d9e4b4f97 --- /dev/null +++ b/log/options.go @@ -0,0 +1,42 @@ +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. +// Messages with a lower level will be discarded. +func LevelOption(level zerolog.Level) Option { + return func(cfg *Config) { + cfg.Level = level + } +} + +// OutputJSONOption sets the output of the logger to JSON. +// By default, the logger outputs to a human-readable format. +func OutputJSONOption() Option { + return func(cfg *Config) { + cfg.OutputJSON = true + } +} diff --git a/log/writer.go b/log/writer.go new file mode 100644 index 000000000000..9c6befef71fe --- /dev/null +++ b/log/writer.go @@ -0,0 +1,41 @@ +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) + } + + var event struct { + Level string `json:"level"` + Module string `json:"module"` + } + + if err := json.Unmarshal(p, &event); err != nil { + return 0, fmt.Errorf("failed to unmarshal event: %w", err) + } + + // only filter module keys + if fw.filter(event.Module, event.Level) { + return len(p), nil + } + + return fw.parent.Write(p) +} diff --git a/log/writer_test.go b/log/writer_test.go new file mode 100644 index 000000000000..fc312efb679b --- /dev/null +++ b/log/writer_test.go @@ -0,0 +1,26 @@ +package log_test + +import ( + "bytes" + "strings" + "testing" + + "cosmossdk.io/log" + "gotest.tools/v3/assert" +) + +func TestFilteredWriter(t *testing.T) { + buf := new(bytes.Buffer) + + level := "consensus:debug,mempool:debug,*:error" + filter, err := log.ParseLogLevel(level) + assert.NilError(t, err) + + logger := log.NewLogger(buf, log.FilterOption(filter)) + logger.Debug("this log line should be displayed", log.ModuleKey, "consensus") + assert.Check(t, strings.Contains(buf.String(), "this log line should be displayed")) + buf.Reset() + + logger.Debug("this log line should be filtered", log.ModuleKey, "server") + assert.Check(t, buf.Len() == 0) +} diff --git a/server/util.go b/server/util.go index c655b283c322..6bb46bd6ddc3 100644 --- a/server/util.go +++ b/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 diff --git a/simapp/go.mod b/simapp/go.mod index 04bd6387b72a..2584950f2e0b 100644 --- a/simapp/go.mod +++ b/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 diff --git a/simapp/go.sum b/simapp/go.sum index ab43b201f895..500f6d84e04c 100644 --- a/simapp/go.sum +++ b/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= diff --git a/tests/go.mod b/tests/go.mod index 1f356314c32e..cb454d27b41d 100644 --- a/tests/go.mod +++ b/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 diff --git a/tests/go.sum b/tests/go.sum index b1f6e3dc1074..22fef38879d5 100644 --- a/tests/go.sum +++ b/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= diff --git a/tools/cosmovisor/cmd/cosmovisor/main.go b/tools/cosmovisor/cmd/cosmovisor/main.go index 44bd80fc6235..206802ac19e3 100644 --- a/tools/cosmovisor/cmd/cosmovisor/main.go +++ b/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 { diff --git a/tools/cosmovisor/process_test.go b/tools/cosmovisor/process_test.go index 8bbd327f541a..02479f77e937 100644 --- a/tools/cosmovisor/process_test.go +++ b/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 diff --git a/tools/cosmovisor/upgrade_test.go b/tools/cosmovisor/upgrade_test.go index dd6be6af4c77..028e6b0d764d 100644 --- a/tools/cosmovisor/upgrade_test.go +++ b/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 diff --git a/tools/rosetta/cmd/rosetta/main.go b/tools/rosetta/cmd/rosetta/main.go index 54bb88b5d161..b5454f2f5490 100644 --- a/tools/rosetta/cmd/rosetta/main.go +++ b/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) ) diff --git a/tools/rosetta/lib/server/server.go b/tools/rosetta/lib/server/server.go index 6b79d5fe79ea..d84c86061a3f 100644 --- a/tools/rosetta/lib/server/server.go +++ b/tools/rosetta/lib/server/server.go @@ -61,7 +61,7 @@ func NewServer(settings Settings) (Server, error) { return Server{}, fmt.Errorf("cannot build asserter: %w", err) } - logger := log.NewLoggerWithKV(os.Stdout, log.ModuleKey, "rosetta") + logger := log.NewLogger(os.Stdout).With(log.ModuleKey, "rosetta") var adapter crgtypes.API switch settings.Offline {