Skip to content

Commit

Permalink
feat(log): wire logger filtering (#15601)
Browse files Browse the repository at this point in the history
  • Loading branch information
julienrbrt authored Mar 30, 2023
1 parent f3110e9 commit d21f58c
Show file tree
Hide file tree
Showing 18 changed files with 170 additions and 76 deletions.
2 changes: 1 addition & 1 deletion go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
5 changes: 3 additions & 2 deletions log/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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-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

Expand Down
4 changes: 2 additions & 2 deletions log/level.go
Original file line number Diff line number Diff line change
Expand Up @@ -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).
Expand Down
67 changes: 26 additions & 41 deletions log/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand Down
42 changes: 42 additions & 0 deletions log/options.go
Original file line number Diff line number Diff line change
@@ -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
}
}
41 changes: 41 additions & 0 deletions log/writer.go
Original file line number Diff line number Diff line change
@@ -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)
}
26 changes: 26 additions & 0 deletions log/writer_test.go
Original file line number Diff line number Diff line change
@@ -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)
}
31 changes: 15 additions & 16 deletions server/util.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion simapp/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions simapp/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
2 changes: 1 addition & 1 deletion tests/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions tests/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
2 changes: 1 addition & 1 deletion tools/cosmovisor/cmd/cosmovisor/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
2 changes: 1 addition & 1 deletion tools/cosmovisor/process_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions tools/cosmovisor/upgrade_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion tools/rosetta/cmd/rosetta/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
)
Expand Down
2 changes: 1 addition & 1 deletion tools/rosetta/lib/server/server.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down

0 comments on commit d21f58c

Please sign in to comment.