From 1299b77ddfc3f8e987f0ed804acfc3469cc48584 Mon Sep 17 00:00:00 2001 From: marbar3778 Date: Mon, 13 Jun 2022 15:20:00 +0200 Subject: [PATCH] filter logging --- libs/log/filter.go | 197 ++++++++++++++++++++++++++++++++++++++++ libs/log/filter_test.go | 137 ++++++++++++++++++++++++++++ libs/log/testing.go | 7 ++ 3 files changed, 341 insertions(+) create mode 100644 libs/log/filter.go create mode 100644 libs/log/filter_test.go diff --git a/libs/log/filter.go b/libs/log/filter.go new file mode 100644 index 000000000..d74ddb7bc --- /dev/null +++ b/libs/log/filter.go @@ -0,0 +1,197 @@ +package log + +import ( + "fmt" +) + +type level byte + +const ( + levelDebug level = 1 << iota + levelInfo + levelError +) + +type filter struct { + next Logger + allowed level // XOR'd levels for default case + initiallyAllowed level // XOR'd levels for initial case + allowedKeyvals map[keyval]level // When key-value match, use this level +} + +type keyval struct { + key interface{} + value interface{} +} + +// NewFilter wraps next and implements filtering. See the commentary on the +// Option functions for a detailed description of how to configure levels. If +// no options are provided, all leveled log events created with Debug, Info or +// Error helper methods are squelched. +func NewFilter(next Logger, options ...Option) Logger { + l := &filter{ + next: next, + allowedKeyvals: make(map[keyval]level), + } + for _, option := range options { + option(l) + } + l.initiallyAllowed = l.allowed + return l +} + +func (l *filter) Info(msg string, keyvals ...interface{}) { + levelAllowed := l.allowed&levelInfo != 0 + if !levelAllowed { + return + } + l.next.Info(msg, keyvals...) +} + +func (l *filter) Debug(msg string, keyvals ...interface{}) { + levelAllowed := l.allowed&levelDebug != 0 + if !levelAllowed { + return + } + l.next.Debug(msg, keyvals...) +} + +func (l *filter) Error(msg string, keyvals ...interface{}) { + levelAllowed := l.allowed&levelError != 0 + if !levelAllowed { + return + } + l.next.Error(msg, keyvals...) +} + +// With implements Logger by constructing a new filter with a keyvals appended +// to the logger. +// +// If custom level was set for a keyval pair using one of the +// Allow*With methods, it is used as the logger's level. +// +// Examples: +// logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto")) +// logger.With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto" +// +// logger = log.NewFilter(logger, log.AllowError(), +// log.AllowInfoWith("module", "crypto"), +// log.AllowNoneWith("user", "Sam")) +// logger.With("module", "crypto", "user", "Sam").Info("Hello") # returns nil +// +// logger = log.NewFilter(logger, +// log.AllowError(), +// log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam")) +// logger.With("user", "Sam").With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto user=Sam" +func (l *filter) With(keyvals ...interface{}) Logger { + keyInAllowedKeyvals := false + + for i := len(keyvals) - 2; i >= 0; i -= 2 { + for kv, allowed := range l.allowedKeyvals { + if keyvals[i] == kv.key { + keyInAllowedKeyvals = true + // Example: + // logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto")) + // logger.With("module", "crypto") + if keyvals[i+1] == kv.value { + return &filter{ + next: l.next.With(keyvals...), + allowed: allowed, // set the desired level + allowedKeyvals: l.allowedKeyvals, + initiallyAllowed: l.initiallyAllowed, + } + } + } + } + } + + // Example: + // logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto")) + // logger.With("module", "main") + if keyInAllowedKeyvals { + return &filter{ + next: l.next.With(keyvals...), + allowed: l.initiallyAllowed, // return back to initially allowed + allowedKeyvals: l.allowedKeyvals, + initiallyAllowed: l.initiallyAllowed, + } + } + + return &filter{ + next: l.next.With(keyvals...), + allowed: l.allowed, // simply continue with the current level + allowedKeyvals: l.allowedKeyvals, + initiallyAllowed: l.initiallyAllowed, + } +} + +//-------------------------------------------------------------------------------- + +// Option sets a parameter for the filter. +type Option func(*filter) + +// AllowLevel returns an option for the given level or error if no option exist +// for such level. +func AllowLevel(lvl string) (Option, error) { + switch lvl { + case "debug": + return AllowDebug(), nil + case "info": + return AllowInfo(), nil + case "error": + return AllowError(), nil + case "none": + return AllowNone(), nil + default: + return nil, fmt.Errorf("expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl) + } +} + +// AllowAll is an alias for AllowDebug. +func AllowAll() Option { + return AllowDebug() +} + +// AllowDebug allows error, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelInfo | levelDebug) +} + +// AllowInfo allows error and info level log events to pass. +func AllowInfo() Option { + return allowed(levelError | levelInfo) +} + +// AllowError allows only error level log events to pass. +func AllowError() Option { + return allowed(levelError) +} + +// AllowNone allows no leveled log events to pass. +func AllowNone() Option { + return allowed(0) +} + +func allowed(allowed level) Option { + return func(l *filter) { l.allowed = allowed } +} + +// AllowDebugWith allows error, info and debug level log events to pass for a specific key value pair. +func AllowDebugWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo | levelDebug } +} + +// AllowInfoWith allows error and info level log events to pass for a specific key value pair. +func AllowInfoWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo } +} + +// AllowErrorWith allows only error level log events to pass for a specific key value pair. +func AllowErrorWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError } +} + +// AllowNoneWith allows no leveled log events to pass for a specific key value pair. +func AllowNoneWith(key interface{}, value interface{}) Option { + return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = 0 } +} diff --git a/libs/log/filter_test.go b/libs/log/filter_test.go new file mode 100644 index 000000000..d4be8edc8 --- /dev/null +++ b/libs/log/filter_test.go @@ -0,0 +1,137 @@ +package log_test + +import ( + "bytes" + "strings" + "testing" + + "github.com/tendermint/tendermint/libs/log" +) + +func TestVariousLevels(t *testing.T) { + testCases := []struct { + name string + allowed log.Option + want string + }{ + { + "AllowAll", + log.AllowAll(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log","message":"here"}`, + `{"level":"info","this is":"info log","message":"here"}`, + `{"level":"error","this is":"error log","message":"here"}`, + }, "\n"), + }, + { + "AllowDebug", + log.AllowDebug(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log","message":"here"}`, + `{"level":"info","this is":"info log","message":"here"}`, + `{"level":"error","this is":"error log","message":"here"}`, + }, "\n"), + }, + { + "AllowInfo", + log.AllowInfo(), + strings.Join([]string{ + `{"level":"info","this is":"info log","message":"here"}`, + `{"level":"error","this is":"error log","message":"here"}`, + }, "\n"), + }, + { + "AllowError", + log.AllowError(), + strings.Join([]string{ + `{"level":"error","this is":"error log","message":"here"}`, + }, "\n"), + }, + { + "AllowNone", + log.AllowNone(), + ``, + }, + } + + for _, tc := range testCases { + tc := tc + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + + logger := log.NewFilter(log.NewWriterLogger(&buf), tc.allowed) + + logger.Debug("here", "this is", "debug log") + logger.Info("here", "this is", "info log") + logger.Error("here", "this is", "error log") + + if want, have := tc.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant:\n%s\nhave:\n%s", want, have) + } + }) + } +} + +func TestLevelContext(t *testing.T) { + var buf bytes.Buffer + logger := log.NewFilter(log.NewWriterLogger(&buf), log.AllowError()) + + logger.Error("foo", "bar", "baz") + + want := `{"level":"error","bar":"baz","message":"foo"}` + have := strings.TrimSpace(buf.String()) + if want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + logger.Info("foo", "bar", "baz") + if want, have := ``, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} +func TestVariousAllowWith(t *testing.T) { + var buf bytes.Buffer + + logger := log.NewWriterLogger(&buf) + + logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value")) + logger1.With("context", "value").Info("foo", "bar", "baz") + + want := `{"level":"info","context":"value","bar":"baz","message":"foo"}` + have := strings.TrimSpace(buf.String()) + if want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger2 := log.NewFilter( + logger, + log.AllowError(), + log.AllowInfoWith("context", "value"), + log.AllowNoneWith("user", "Sam"), + ) + + logger2.With("context", "value", "user", "Sam").Info("foo", "bar", "baz") + if want, have := ``, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } + + buf.Reset() + + logger3 := log.NewFilter( + logger, + log.AllowError(), + log.AllowInfoWith("context", "value"), + log.AllowNoneWith("user", "Sam"), + ) + + logger3.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz") + + want = `{"level":"info","user":"Sam","context":"value","bar":"baz","message":"foo"}` + have = strings.TrimSpace(buf.String()) + if want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} diff --git a/libs/log/testing.go b/libs/log/testing.go index 464a7036f..2898f4ddc 100644 --- a/libs/log/testing.go +++ b/libs/log/testing.go @@ -1,6 +1,7 @@ package log import ( + "io" "testing" "github.com/rs/zerolog" @@ -49,3 +50,9 @@ func (tw testingWriter) Write(in []byte) (int, error) { tw.t.Log(string(in)) return len(in), nil } + +func NewWriterLogger(writer io.Writer) Logger { + return defaultLogger{ + Logger: zerolog.New(writer).With().Logger(), + } +}