From 795adb1ae4608617e8531746581a4f475988ff19 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Mon, 20 Feb 2017 20:46:56 -0500 Subject: [PATCH 1/8] log: More detailed benchmarks for experimental_level package. --- log/experimental_level/benchmark_test.go | 101 +++++++++++++---------- 1 file changed, 57 insertions(+), 44 deletions(-) diff --git a/log/experimental_level/benchmark_test.go b/log/experimental_level/benchmark_test.go index 649e33de4..7b6c8e8d8 100644 --- a/log/experimental_level/benchmark_test.go +++ b/log/experimental_level/benchmark_test.go @@ -8,52 +8,65 @@ import ( "github.com/go-kit/kit/log/experimental_level" ) -func BenchmarkNopBaseline(b *testing.B) { - benchmarkRunner(b, log.NewNopLogger()) -} - -func BenchmarkNopDisallowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewNopLogger(), - level.Allowed(level.AllowInfoAndAbove()))) -} - -func BenchmarkNopAllowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewNopLogger(), - level.Allowed(level.AllowAll()))) -} - -func BenchmarkJSONBaseline(b *testing.B) { - benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard)) -} - -func BenchmarkJSONDisallowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewJSONLogger(ioutil.Discard), - level.Allowed(level.AllowInfoAndAbove()))) -} - -func BenchmarkJSONAllowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewJSONLogger(ioutil.Discard), - level.Allowed(level.AllowAll()))) -} - -func BenchmarkLogfmtBaseline(b *testing.B) { - benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) -} +func Benchmark(b *testing.B) { + contexts := []struct { + name string + context func(log.Logger) log.Logger + }{ + {"NoContext", func(l log.Logger) log.Logger { + return l + }}, + {"TimeContext", func(l log.Logger) log.Logger { + return log.NewContext(l).With("time", log.DefaultTimestampUTC) + }}, + {"CallerContext", func(l log.Logger) log.Logger { + return log.NewContext(l).With("caller", log.DefaultCaller) + }}, + {"TimeCallerReqIDContext", func(l log.Logger) log.Logger { + return log.NewContext(l).With("time", log.DefaultTimestampUTC, "caller", log.DefaultCaller, "reqID", 29) + }}, + } -func BenchmarkLogfmtDisallowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), - level.Allowed(level.AllowInfoAndAbove()))) -} + loggers := []struct { + name string + logger log.Logger + }{ + {"Nop", log.NewNopLogger()}, + {"Logfmt", log.NewLogfmtLogger(ioutil.Discard)}, + {"JSON", log.NewJSONLogger(ioutil.Discard)}, + } -func BenchmarkLogfmtAllowedLevel(b *testing.B) { - benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), - level.Allowed(level.AllowAll()))) -} + filters := []struct { + name string + filter func(log.Logger) log.Logger + }{ + {"Baseline", func(l log.Logger) log.Logger { + return l + }}, + {"DisallowedLevel", func(l log.Logger) log.Logger { + return level.New(l, level.Allowed(level.AllowInfoAndAbove())) + }}, + {"AllowedLevel", func(l log.Logger) log.Logger { + return level.New(l, level.Allowed(level.AllowAll())) + }}, + } -func benchmarkRunner(b *testing.B, logger log.Logger) { - b.ResetTimer() - b.ReportAllocs() - for i := 0; i < b.N; i++ { - level.Debug(logger).Log("foo", "bar") + for _, c := range contexts { + b.Run(c.name, func(b *testing.B) { + for _, f := range filters { + b.Run(f.name, func(b *testing.B) { + for _, l := range loggers { + b.Run(l.name, func(b *testing.B) { + logger := c.context(f.filter(l.logger)) + b.ResetTimer() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + level.Debug(logger).Log("foo", "bar") + } + }) + } + }) + } + }) } } From be51b44f195688281f8656381f2ff88480021567 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Thu, 23 Feb 2017 13:59:22 -0500 Subject: [PATCH 2/8] log: Reimplement experimental_level package with a bit set. --- log/experimental_level/benchmark_test.go | 4 +- log/experimental_level/doc.go | 11 +- log/experimental_level/example_test.go | 25 +++ log/experimental_level/level.go | 216 +++++++++++------------ log/experimental_level/level_test.go | 16 +- 5 files changed, 144 insertions(+), 128 deletions(-) create mode 100644 log/experimental_level/example_test.go diff --git a/log/experimental_level/benchmark_test.go b/log/experimental_level/benchmark_test.go index 7b6c8e8d8..11aaec1b4 100644 --- a/log/experimental_level/benchmark_test.go +++ b/log/experimental_level/benchmark_test.go @@ -44,10 +44,10 @@ func Benchmark(b *testing.B) { return l }}, {"DisallowedLevel", func(l log.Logger) log.Logger { - return level.New(l, level.Allowed(level.AllowInfoAndAbove())) + return level.NewFilter(l, level.AllowInfoAndAbove()) }}, {"AllowedLevel", func(l log.Logger) log.Logger { - return level.New(l, level.Allowed(level.AllowAll())) + return level.NewFilter(l, level.AllowAll()) }}, } diff --git a/log/experimental_level/doc.go b/log/experimental_level/doc.go index 6c0055973..65f02a49e 100644 --- a/log/experimental_level/doc.go +++ b/log/experimental_level/doc.go @@ -2,11 +2,11 @@ // definitely have breaking changes and may be deleted altogether. Be warned! // // To use the level package, create a logger as per normal in your func main, -// and wrap it with level.New. +// and wrap it with level.NewFilter. // // var logger log.Logger // logger = log.NewLogfmtLogger(os.Stderr) -// logger = level.New(logger, level.Allowed(level.AllowInfoAndAbove())) // <-- +// logger = level.NewFilter(logger, level.AllowInfoAndAbove()) // <-- // logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) // // Then, at the callsites, use one of the level.Debug, Info, Warn, or Error @@ -19,9 +19,6 @@ // } // // The leveled logger allows precise control over what should happen if a log -// event is emitted without a level key, or if a squelched level is used. Check -// the Option functions for details. And, you can easily use non-default level -// values: create new string constants for whatever you want to change, pass -// them explicitly to the Allowed Option function, and write your own level.Foo-style -// helper methods. +// event is emitted without a level key, or if a squelched level is used. +// Check the Option functions for details. package level diff --git a/log/experimental_level/example_test.go b/log/experimental_level/example_test.go new file mode 100644 index 000000000..54d65000b --- /dev/null +++ b/log/experimental_level/example_test.go @@ -0,0 +1,25 @@ +package level_test + +import ( + "errors" + "os" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/experimental_level" +) + +func Example_basic() { + // setup logger with level filter + logger := log.NewLogfmtLogger(os.Stdout) + logger = level.NewFilter(logger, level.AllowInfoAndAbove()) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + // use level helpers to log at different levels + level.Error(logger).Log("err", errors.New("bad data")) + level.Info(logger).Log("event", "data saved") + level.Debug(logger).Log("next item", 17) // filtered + + // Output: + // level=error caller=example_test.go:18 err="bad data" + // level=info caller=example_test.go:19 event="data saved" +} diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index 6dfd71adb..a80a3da89 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -1,142 +1,58 @@ package level -import ( - "github.com/go-kit/kit/log" -) - -var ( - levelKey = "level" - errorLevelValue = "error" - warnLevelValue = "warn" - infoLevelValue = "info" - debugLevelValue = "debug" -) - -// AllowAll is an alias for AllowDebugAndAbove. -func AllowAll() []string { - return AllowDebugAndAbove() -} - -// AllowDebugAndAbove allows all of the four default log levels. -// Its return value may be provided with the Allowed Option. -func AllowDebugAndAbove() []string { - return []string{errorLevelValue, warnLevelValue, infoLevelValue, debugLevelValue} -} - -// AllowInfoAndAbove allows the default info, warn, and error log levels. -// Its return value may be provided with the Allowed Option. -func AllowInfoAndAbove() []string { - return []string{errorLevelValue, warnLevelValue, infoLevelValue} -} - -// AllowWarnAndAbove allows the default warn and error log levels. -// Its return value may be provided with the Allowed Option. -func AllowWarnAndAbove() []string { - return []string{errorLevelValue, warnLevelValue} -} - -// AllowErrorOnly allows only the default error log level. -// Its return value may be provided with the Allowed Option. -func AllowErrorOnly() []string { - return []string{errorLevelValue} -} - -// AllowNone allows none of the default log levels. -// Its return value may be provided with the Allowed Option. -func AllowNone() []string { - return []string{} -} +import "github.com/go-kit/kit/log" -// Error returns a logger with the level key set to ErrorLevelValue. +// Error returns a logger that includes an error level keyval. func Error(logger log.Logger) log.Logger { return log.NewContext(logger).WithPrefix(levelKey, errorLevelValue) } -// Warn returns a logger with the level key set to WarnLevelValue. +// Warn returns a logger that includes a warn level keyval. func Warn(logger log.Logger) log.Logger { return log.NewContext(logger).WithPrefix(levelKey, warnLevelValue) } -// Info returns a logger with the level key set to InfoLevelValue. +// Info returns a logger that includes an info level keyval. func Info(logger log.Logger) log.Logger { return log.NewContext(logger).WithPrefix(levelKey, infoLevelValue) } -// Debug returns a logger with the level key set to DebugLevelValue. +// Debug returns a logger that includes a debug level keyval. func Debug(logger log.Logger) log.Logger { return log.NewContext(logger).WithPrefix(levelKey, debugLevelValue) } -// New wraps the logger and implements level checking. 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 level.Debug, -// Info, Warn or Error helper methods will be squelched. -func New(next log.Logger, options ...Option) log.Logger { - l := logger{ +// NewFilter wraps next and implements level 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, Warn or Error helper methods are squelched and non-leveled log +// events are passed to next unmodified. +func NewFilter(next log.Logger, options ...Option) log.Logger { + l := &logger{ next: next, } for _, option := range options { - option(&l) + option(l) } - return &l + return l } -// Allowed enumerates the accepted log levels. If a log event is encountered -// with a level key set to a value that isn't explicitly allowed, the event -// will be squelched, and ErrNotAllowed returned. -func Allowed(allowed []string) Option { - return func(l *logger) { l.allowed = makeSet(allowed) } -} - -// ErrNoLevel is returned to the caller when SquelchNoLevel is true, and Log -// is invoked without a level key. By default, ErrNoLevel is nil; in this -// case, the log event is squelched with no error. -func ErrNotAllowed(err error) Option { - return func(l *logger) { l.errNotAllowed = err } -} - -// SquelchNoLevel will squelch log events with no level key, so that they -// don't proceed through to the wrapped logger. If SquelchNoLevel is set to -// true and a log event is squelched in this way, ErrNoLevel is returned to -// the caller. -func SquelchNoLevel(squelch bool) Option { - return func(l *logger) { l.squelchNoLevel = squelch } -} - -// ErrNoLevel is returned to the caller when SquelchNoLevel is true, and Log -// is invoked without a level key. By default, ErrNoLevel is nil; in this -// case, the log event is squelched with no error. -func ErrNoLevel(err error) Option { - return func(l *logger) { l.errNoLevel = err } -} - -// Option sets a parameter for the leveled logger. -type Option func(*logger) - type logger struct { next log.Logger - allowed map[string]struct{} - errNotAllowed error + allowed level squelchNoLevel bool + errNotAllowed error errNoLevel error } func (l *logger) Log(keyvals ...interface{}) error { var hasLevel, levelAllowed bool - for i := 0; i < len(keyvals); i += 2 { - if k, ok := keyvals[i].(string); !ok || k != levelKey { - continue - } - hasLevel = true - if i >= len(keyvals) { - continue + for i := 1; i < len(keyvals); i += 2 { + if v, ok := keyvals[i].(*levelValue); ok { + hasLevel = true + levelAllowed = l.allowed&v.level != 0 + break } - v, ok := keyvals[i+1].(string) - if !ok { - continue - } - _, levelAllowed = l.allowed[v] - break } if !hasLevel && l.squelchNoLevel { return l.errNoLevel @@ -147,10 +63,88 @@ func (l *logger) Log(keyvals ...interface{}) error { return l.next.Log(keyvals...) } -func makeSet(a []string) map[string]struct{} { - m := make(map[string]struct{}, len(a)) - for _, s := range a { - m[s] = struct{}{} - } - return m +// Option sets a parameter for the leveled logger. +type Option func(*logger) + +// AllowAll is an alias for AllowDebugAndAbove. +func AllowAll() Option { + return AllowDebugAndAbove() +} + +// AllowDebugAndAbove allows all of the four default log levels. +func AllowDebugAndAbove() Option { + return allowed(levelDebug | levelInfo | levelWarn | levelError) +} + +// AllowInfoAndAbove allows the default info, warn, and error log levels. +func AllowInfoAndAbove() Option { + return allowed(levelInfo | levelWarn | levelError) +} + +// AllowWarnAndAbove allows the default warn and error log levels. +func AllowWarnAndAbove() Option { + return allowed(levelWarn | levelError) +} + +// AllowErrorOnly allows only the default error log level. +func AllowErrorOnly() Option { + return allowed(levelError) +} + +// AllowNone allows none of the default log levels. +func AllowNone() Option { + return allowed(0) +} + +func allowed(allowed level) Option { + return func(l *logger) { l.allowed = allowed } +} + +// ErrNotAllowed sets the error to return from Log when it squelches a log +// event below the configured filtering level. By default, ErrNotAllowed is +// nil; in this case, the log event is squelched with no error. +func ErrNotAllowed(err error) Option { + return func(l *logger) { l.errNotAllowed = err } +} + +// SquelchNoLevel instructs Log to squelch log events with no level, so that +// they don't proceed through to the wrapped logger. If SquelchNoLevel is set +// to true and a log event is squelched in this way, the error value +// configured with ErrNoLevel is returned to the caller. +func SquelchNoLevel(squelch bool) Option { + return func(l *logger) { l.squelchNoLevel = squelch } +} + +// ErrNoLevel sets the error to return from Log when it squelches a log event +// with no level. By default, ErrNoLevel is nil; in this case, the log event +// is squelched with no error. +func ErrNoLevel(err error) Option { + return func(l *logger) { l.errNoLevel = err } +} + +const levelKey = "level" + +var ( + errorLevelValue = &levelValue{level: levelError, name: "error"} + warnLevelValue = &levelValue{level: levelWarn, name: "warn"} + infoLevelValue = &levelValue{level: levelInfo, name: "info"} + debugLevelValue = &levelValue{level: levelDebug, name: "debug"} +) + +type level byte + +const ( + levelDebug level = 1 << iota + levelInfo + levelWarn + levelError +) + +type levelValue struct { + name string + level +} + +func (v *levelValue) String() string { + return v.name } diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go index f067b43bb..f8642a9c3 100644 --- a/log/experimental_level/level_test.go +++ b/log/experimental_level/level_test.go @@ -12,7 +12,7 @@ import ( func TestVariousLevels(t *testing.T) { for _, testcase := range []struct { - allowed []string + allowed level.Option want string }{ { @@ -60,7 +60,7 @@ func TestVariousLevels(t *testing.T) { }, } { var buf bytes.Buffer - logger := level.New(log.NewJSONLogger(&buf), level.Allowed(testcase.allowed)) + logger := level.NewFilter(log.NewJSONLogger(&buf), testcase.allowed) level.Debug(logger).Log("this is", "debug log") level.Info(logger).Log("this is", "info log") @@ -76,10 +76,10 @@ func TestVariousLevels(t *testing.T) { func TestErrNotAllowed(t *testing.T) { myError := errors.New("squelched!") opts := []level.Option{ - level.Allowed(level.AllowWarnAndAbove()), + level.AllowWarnAndAbove(), level.ErrNotAllowed(myError), } - logger := level.New(log.NewNopLogger(), opts...) + logger := level.NewFilter(log.NewNopLogger(), opts...) if want, have := myError, level.Info(logger).Log("foo", "bar"); want != have { t.Errorf("want %#+v, have %#+v", want, have) @@ -98,7 +98,7 @@ func TestErrNoLevel(t *testing.T) { level.SquelchNoLevel(true), level.ErrNoLevel(myError), } - logger := level.New(log.NewJSONLogger(&buf), opts...) + logger := level.NewFilter(log.NewJSONLogger(&buf), opts...) if want, have := myError, logger.Log("foo", "bar"); want != have { t.Errorf("want %v, have %v", want, have) @@ -114,7 +114,7 @@ func TestAllowNoLevel(t *testing.T) { level.SquelchNoLevel(false), level.ErrNoLevel(errors.New("I should never be returned!")), } - logger := level.New(log.NewJSONLogger(&buf), opts...) + logger := level.NewFilter(log.NewJSONLogger(&buf), opts...) if want, have := error(nil), logger.Log("foo", "bar"); want != have { t.Errorf("want %v, have %v", want, have) @@ -131,7 +131,7 @@ func TestLevelContext(t *testing.T) { // log.DefaultCaller as per normal. var logger log.Logger logger = log.NewLogfmtLogger(&buf) - logger = level.New(logger, level.Allowed(level.AllowAll())) + logger = level.NewFilter(logger, level.AllowAll()) logger = log.NewContext(logger).With("caller", log.DefaultCaller) level.Info(logger).Log("foo", "bar") @@ -148,7 +148,7 @@ func TestContextLevel(t *testing.T) { var logger log.Logger logger = log.NewLogfmtLogger(&buf) logger = log.NewContext(logger).With("caller", log.Caller(5)) - logger = level.New(logger, level.Allowed(level.AllowAll())) + logger = level.NewFilter(logger, level.AllowAll()) level.Info(logger).Log("foo", "bar") if want, have := `caller=level_test.go:153 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { From 5ffd9f00238d5e14c45d736f259142fa54b12074 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Thu, 23 Feb 2017 14:52:36 -0500 Subject: [PATCH 3/8] Test that level values are correctly formatted in Logfmt and JSON. --- log/experimental_level/level_test.go | 44 ++++++++++++++++++++++++---- 1 file changed, 38 insertions(+), 6 deletions(-) diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go index f8642a9c3..d2844639c 100644 --- a/log/experimental_level/level_test.go +++ b/log/experimental_level/level_test.go @@ -3,6 +3,7 @@ package level_test import ( "bytes" "errors" + "io" "strings" "testing" @@ -104,7 +105,7 @@ func TestErrNoLevel(t *testing.T) { t.Errorf("want %v, have %v", want, have) } if want, have := ``, strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) + t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -120,7 +121,7 @@ func TestAllowNoLevel(t *testing.T) { t.Errorf("want %v, have %v", want, have) } if want, have := `{"foo":"bar"}`, strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) + t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -135,8 +136,8 @@ func TestLevelContext(t *testing.T) { logger = log.NewContext(logger).With("caller", log.DefaultCaller) level.Info(logger).Log("foo", "bar") - if want, have := `level=info caller=level_test.go:137 foo=bar`, strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) + if want, have := `level=info caller=level_test.go:138 foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -151,7 +152,38 @@ func TestContextLevel(t *testing.T) { logger = level.NewFilter(logger, level.AllowAll()) level.Info(logger).Log("foo", "bar") - if want, have := `caller=level_test.go:153 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) + if want, have := `caller=level_test.go:154 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) + } +} + +func TestLevelFormatting(t *testing.T) { + testCases := []struct { + name string + format func(io.Writer) log.Logger + output string + }{ + { + name: "logfmt", + format: log.NewLogfmtLogger, + output: `level=info foo=bar`, + }, + { + name: "JSON", + format: log.NewJSONLogger, + output: `{"foo":"bar","level":"info"}`, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + + logger := tc.format(&buf) + level.Info(logger).Log("foo", "bar") + if want, have := tc.output, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant: '%s'\nhave '%s'", want, have) + } + }) } } From 6a12b3162160a71abf7458cdfccdc8aa0cca0ba0 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Thu, 23 Feb 2017 19:49:01 -0500 Subject: [PATCH 4/8] Preallocate level key interface{} value. --- log/experimental_level/level.go | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index a80a3da89..1669db990 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -122,13 +122,12 @@ func ErrNoLevel(err error) Option { return func(l *logger) { l.errNoLevel = err } } -const levelKey = "level" - var ( - errorLevelValue = &levelValue{level: levelError, name: "error"} - warnLevelValue = &levelValue{level: levelWarn, name: "warn"} - infoLevelValue = &levelValue{level: levelInfo, name: "info"} - debugLevelValue = &levelValue{level: levelDebug, name: "debug"} + levelKey interface{} = "level" + errorLevelValue = &levelValue{level: levelError, name: "error"} + warnLevelValue = &levelValue{level: levelWarn, name: "warn"} + infoLevelValue = &levelValue{level: levelInfo, name: "info"} + debugLevelValue = &levelValue{level: levelDebug, name: "debug"} ) type level byte From 5dc79025f26fac1377065bed218d751ae1e917cc Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Fri, 24 Feb 2017 15:55:50 -0500 Subject: [PATCH 5/8] log: More concise functions names for experimental_level package. --- log/experimental_level/benchmark_test.go | 2 +- log/experimental_level/example_test.go | 2 +- log/experimental_level/level.go | 37 ++++++++++++------------ log/experimental_level/level_test.go | 10 +++---- 4 files changed, 26 insertions(+), 25 deletions(-) diff --git a/log/experimental_level/benchmark_test.go b/log/experimental_level/benchmark_test.go index 11aaec1b4..65b06c467 100644 --- a/log/experimental_level/benchmark_test.go +++ b/log/experimental_level/benchmark_test.go @@ -44,7 +44,7 @@ func Benchmark(b *testing.B) { return l }}, {"DisallowedLevel", func(l log.Logger) log.Logger { - return level.NewFilter(l, level.AllowInfoAndAbove()) + return level.NewFilter(l, level.AllowInfo()) }}, {"AllowedLevel", func(l log.Logger) log.Logger { return level.NewFilter(l, level.AllowAll()) diff --git a/log/experimental_level/example_test.go b/log/experimental_level/example_test.go index 54d65000b..d18187712 100644 --- a/log/experimental_level/example_test.go +++ b/log/experimental_level/example_test.go @@ -11,7 +11,7 @@ import ( func Example_basic() { // setup logger with level filter logger := log.NewLogfmtLogger(os.Stdout) - logger = level.NewFilter(logger, level.AllowInfoAndAbove()) + logger = level.NewFilter(logger, level.AllowInfo()) logger = log.NewContext(logger).With("caller", log.DefaultCaller) // use level helpers to log at different levels diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index 1669db990..3d29f1549 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -66,32 +66,32 @@ func (l *logger) Log(keyvals ...interface{}) error { // Option sets a parameter for the leveled logger. type Option func(*logger) -// AllowAll is an alias for AllowDebugAndAbove. +// AllowAll is an alias for AllowDebug. func AllowAll() Option { - return AllowDebugAndAbove() + return AllowDebug() } -// AllowDebugAndAbove allows all of the four default log levels. -func AllowDebugAndAbove() Option { - return allowed(levelDebug | levelInfo | levelWarn | levelError) +// AllowDebug allows error, warn, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelWarn | levelInfo | levelDebug) } -// AllowInfoAndAbove allows the default info, warn, and error log levels. -func AllowInfoAndAbove() Option { - return allowed(levelInfo | levelWarn | levelError) +// AllowInfo allows error, warn and info level log events to pass. +func AllowInfo() Option { + return allowed(levelError | levelWarn | levelInfo) } -// AllowWarnAndAbove allows the default warn and error log levels. -func AllowWarnAndAbove() Option { - return allowed(levelWarn | levelError) +// AllowWarn allows error and warn level log events to pass. +func AllowWarn() Option { + return allowed(levelError | levelWarn) } -// AllowErrorOnly allows only the default error log level. -func AllowErrorOnly() Option { +// AllowError allows only error level log events to pass. +func AllowError() Option { return allowed(levelError) } -// AllowNone allows none of the default log levels. +// AllowNone allows no leveled log events to pass. func AllowNone() Option { return allowed(0) } @@ -101,8 +101,9 @@ func allowed(allowed level) Option { } // ErrNotAllowed sets the error to return from Log when it squelches a log -// event below the configured filtering level. By default, ErrNotAllowed is -// nil; in this case, the log event is squelched with no error. +// event disallowed by the configured Allow[Level] option. By default, +// ErrNotAllowed is nil; in this case the log event is squelched with no +// error. func ErrNotAllowed(err error) Option { return func(l *logger) { l.errNotAllowed = err } } @@ -116,8 +117,8 @@ func SquelchNoLevel(squelch bool) Option { } // ErrNoLevel sets the error to return from Log when it squelches a log event -// with no level. By default, ErrNoLevel is nil; in this case, the log event -// is squelched with no error. +// with no level. By default, ErrNoLevel is nil; in this case the log event is +// squelched with no error. func ErrNoLevel(err error) Option { return func(l *logger) { l.errNoLevel = err } } diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go index d2844639c..b17307209 100644 --- a/log/experimental_level/level_test.go +++ b/log/experimental_level/level_test.go @@ -26,7 +26,7 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowDebugAndAbove(), + level.AllowDebug(), strings.Join([]string{ `{"level":"debug","this is":"debug log"}`, `{"level":"info","this is":"info log"}`, @@ -35,7 +35,7 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowInfoAndAbove(), + level.AllowInfo(), strings.Join([]string{ `{"level":"info","this is":"info log"}`, `{"level":"warn","this is":"warn log"}`, @@ -43,14 +43,14 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowWarnAndAbove(), + level.AllowWarn(), strings.Join([]string{ `{"level":"warn","this is":"warn log"}`, `{"level":"error","this is":"error log"}`, }, "\n"), }, { - level.AllowErrorOnly(), + level.AllowError(), strings.Join([]string{ `{"level":"error","this is":"error log"}`, }, "\n"), @@ -77,7 +77,7 @@ func TestVariousLevels(t *testing.T) { func TestErrNotAllowed(t *testing.T) { myError := errors.New("squelched!") opts := []level.Option{ - level.AllowWarnAndAbove(), + level.AllowWarn(), level.ErrNotAllowed(myError), } logger := level.NewFilter(log.NewNopLogger(), opts...) From 72d4c4d3eef0c239bf4908143d908dde97305cf6 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Wed, 1 Mar 2017 18:31:49 -0500 Subject: [PATCH 6/8] log: Add level.NewInjector and export Key and [Level]Value functions. --- log/experimental_level/level.go | 66 +++++++++++++++++++++------- log/experimental_level/level_test.go | 60 +++++++++++++++++++------ 2 files changed, 97 insertions(+), 29 deletions(-) diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index 3d29f1549..2aec7bc1d 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -2,24 +2,24 @@ package level import "github.com/go-kit/kit/log" -// Error returns a logger that includes an error level keyval. +// Error returns a logger that includes a Key/ErrorValue pair. func Error(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, errorLevelValue) + return log.NewContext(logger).WithPrefix(key, errorValue) } -// Warn returns a logger that includes a warn level keyval. +// Warn returns a logger that includes a Key/WarnValue pair. func Warn(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, warnLevelValue) + return log.NewContext(logger).WithPrefix(key, warnValue) } -// Info returns a logger that includes an info level keyval. +// Info returns a logger that includes a Key/InfoValue pair. func Info(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, infoLevelValue) + return log.NewContext(logger).WithPrefix(key, infoValue) } -// Debug returns a logger that includes a debug level keyval. +// Debug returns a logger that includes a Key/DebugValue pair. func Debug(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, debugLevelValue) + return log.NewContext(logger).WithPrefix(key, debugValue) } // NewFilter wraps next and implements level filtering. See the commentary on @@ -123,12 +123,47 @@ func ErrNoLevel(err error) Option { return func(l *logger) { l.errNoLevel = err } } +func NewInjector(next log.Logger, level Value) log.Logger { + return &injector{ + next: next, + level: level, + } +} + +type injector struct { + next log.Logger + level interface{} +} + +func (l *injector) Log(keyvals ...interface{}) error { + for i := 1; i < len(keyvals); i += 2 { + if _, ok := keyvals[i].(*levelValue); ok { + return l.next.Log(keyvals...) + } + } + kvs := make([]interface{}, len(keyvals)+2) + kvs[0], kvs[1] = key, l.level + copy(kvs[2:], keyvals) + return l.next.Log(kvs...) +} + +type Value interface { + String() string + levelVal() +} + +func Key() interface{} { return key } +func ErrorValue() Value { return errorValue } +func WarnValue() Value { return warnValue } +func InfoValue() Value { return infoValue } +func DebugValue() Value { return debugValue } + var ( - levelKey interface{} = "level" - errorLevelValue = &levelValue{level: levelError, name: "error"} - warnLevelValue = &levelValue{level: levelWarn, name: "warn"} - infoLevelValue = &levelValue{level: levelInfo, name: "info"} - debugLevelValue = &levelValue{level: levelDebug, name: "debug"} + key interface{} = "level" + errorValue = &levelValue{level: levelError, name: "error"} + warnValue = &levelValue{level: levelWarn, name: "warn"} + infoValue = &levelValue{level: levelInfo, name: "info"} + debugValue = &levelValue{level: levelDebug, name: "debug"} ) type level byte @@ -145,6 +180,5 @@ type levelValue struct { level } -func (v *levelValue) String() string { - return v.name -} +func (v *levelValue) String() string { return v.name } +func (v *levelValue) levelVal() {} diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go index b17307209..8027daa59 100644 --- a/log/experimental_level/level_test.go +++ b/log/experimental_level/level_test.go @@ -12,11 +12,13 @@ import ( ) func TestVariousLevels(t *testing.T) { - for _, testcase := range []struct { + testCases := []struct { + name string allowed level.Option want string }{ { + "AllowAll", level.AllowAll(), strings.Join([]string{ `{"level":"debug","this is":"debug log"}`, @@ -26,6 +28,7 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { + "AllowDebug", level.AllowDebug(), strings.Join([]string{ `{"level":"debug","this is":"debug log"}`, @@ -35,6 +38,7 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { + "AllowDebug", level.AllowInfo(), strings.Join([]string{ `{"level":"info","this is":"info log"}`, @@ -43,6 +47,7 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { + "AllowWarn", level.AllowWarn(), strings.Join([]string{ `{"level":"warn","this is":"warn log"}`, @@ -50,27 +55,33 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { + "AllowError", level.AllowError(), strings.Join([]string{ `{"level":"error","this is":"error log"}`, }, "\n"), }, { + "AllowNone", level.AllowNone(), ``, }, - } { - var buf bytes.Buffer - logger := level.NewFilter(log.NewJSONLogger(&buf), testcase.allowed) + } - level.Debug(logger).Log("this is", "debug log") - level.Info(logger).Log("this is", "info log") - level.Warn(logger).Log("this is", "warn log") - level.Error(logger).Log("this is", "error log") + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + logger := level.NewFilter(log.NewJSONLogger(&buf), tc.allowed) + + level.Debug(logger).Log("this is", "debug log") + level.Info(logger).Log("this is", "info log") + level.Warn(logger).Log("this is", "warn log") + level.Error(logger).Log("this is", "error log") - if want, have := testcase.want, strings.TrimSpace(buf.String()); want != have { - t.Errorf("given Allowed=%v: want\n%s\nhave\n%s", testcase.allowed, want, have) - } + if want, have := tc.want, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant:\n%s\nhave:\n%s", want, have) + } + }) } } @@ -136,7 +147,7 @@ func TestLevelContext(t *testing.T) { logger = log.NewContext(logger).With("caller", log.DefaultCaller) level.Info(logger).Log("foo", "bar") - if want, have := `level=info caller=level_test.go:138 foo=bar`, strings.TrimSpace(buf.String()); want != have { + if want, have := `level=info caller=level_test.go:149 foo=bar`, strings.TrimSpace(buf.String()); want != have { t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -152,7 +163,7 @@ func TestContextLevel(t *testing.T) { logger = level.NewFilter(logger, level.AllowAll()) level.Info(logger).Log("foo", "bar") - if want, have := `caller=level_test.go:154 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + if want, have := `caller=level_test.go:165 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -187,3 +198,26 @@ func TestLevelFormatting(t *testing.T) { }) } } + +func TestInjector(t *testing.T) { + var ( + output []interface{} + logger log.Logger + ) + + logger = log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + }) + logger = level.NewInjector(logger, level.InfoValue()) + + logger.Log("foo", "bar") + if got, want := len(output), 4; got != want { + t.Errorf("missing level not injected: got len==%d, want len==%d", got, want) + } + + level.Error(logger).Log("foo", "bar") + if got, want := len(output), 4; got != want { + t.Errorf("leveled record modified: got len==%d, want len==%d", got, want) + } +} From 6d9bb5f6ad72971aa9956331a355f686af9b5af8 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Wed, 1 Mar 2017 19:59:18 -0500 Subject: [PATCH 7/8] log: Add docs for new types and functions. --- log/experimental_level/doc.go | 6 ++-- log/experimental_level/level.go | 44 ++++++++++++++++++++-------- log/experimental_level/level_test.go | 12 ++++++++ 3 files changed, 47 insertions(+), 15 deletions(-) diff --git a/log/experimental_level/doc.go b/log/experimental_level/doc.go index 65f02a49e..63a446956 100644 --- a/log/experimental_level/doc.go +++ b/log/experimental_level/doc.go @@ -18,7 +18,7 @@ // level.Error(logger).Log("value", value) // } // -// The leveled logger allows precise control over what should happen if a log -// event is emitted without a level key, or if a squelched level is used. -// Check the Option functions for details. +// NewFilter allows precise control over what happens when a log event is +// emitted without a level key, or if a squelched level is used. Check the +// Option functions for details. package level diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index 2aec7bc1d..d36a6b1d3 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -4,22 +4,22 @@ import "github.com/go-kit/kit/log" // Error returns a logger that includes a Key/ErrorValue pair. func Error(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(key, errorValue) + return log.NewContext(logger).WithPrefix(Key(), ErrorValue()) } // Warn returns a logger that includes a Key/WarnValue pair. func Warn(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(key, warnValue) + return log.NewContext(logger).WithPrefix(Key(), WarnValue()) } // Info returns a logger that includes a Key/InfoValue pair. func Info(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(key, infoValue) + return log.NewContext(logger).WithPrefix(Key(), InfoValue()) } // Debug returns a logger that includes a Key/DebugValue pair. func Debug(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(key, debugValue) + return log.NewContext(logger).WithPrefix(Key(), DebugValue()) } // NewFilter wraps next and implements level filtering. See the commentary on @@ -123,6 +123,8 @@ func ErrNoLevel(err error) Option { return func(l *logger) { l.errNoLevel = err } } +// NewInjector wraps next and returns a logger that adds a Key/level pair to +// the beginning of log events that don't already contain a level. func NewInjector(next log.Logger, level Value) log.Logger { return &injector{ next: next, @@ -147,23 +149,41 @@ func (l *injector) Log(keyvals ...interface{}) error { return l.next.Log(kvs...) } +// Value is the interface that each of the canonical level values implement. +// It contains unexported methods that prevent types from other packages from +// implementing it and guaranteeing that NewFilter can distinguish the levels +// defined in this package from all other values. type Value interface { String() string levelVal() } -func Key() interface{} { return key } +// Key returns the unique key added to log events by the loggers in this +// package. +func Key() interface{} { return key } + +// ErrorValue returns the unique value added to log events by Error. func ErrorValue() Value { return errorValue } -func WarnValue() Value { return warnValue } -func InfoValue() Value { return infoValue } + +// WarnValue returns the unique value added to log events by Warn. +func WarnValue() Value { return warnValue } + +// InfoValue returns the unique value added to log events by Info. +func InfoValue() Value { return infoValue } + +// DebugValue returns the unique value added to log events by Warn. func DebugValue() Value { return debugValue } var ( - key interface{} = "level" - errorValue = &levelValue{level: levelError, name: "error"} - warnValue = &levelValue{level: levelWarn, name: "warn"} - infoValue = &levelValue{level: levelInfo, name: "info"} - debugValue = &levelValue{level: levelDebug, name: "debug"} + // key is of type interfae{} so that it allocates once during package + // initialization and avoids allocating every type the value is added to a + // []interface{} later. + key interface{} = "level" + + errorValue = &levelValue{level: levelError, name: "error"} + warnValue = &levelValue{level: levelWarn, name: "warn"} + infoValue = &levelValue{level: levelInfo, name: "info"} + debugValue = &levelValue{level: levelDebug, name: "debug"} ) type level byte diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go index 8027daa59..047762454 100644 --- a/log/experimental_level/level_test.go +++ b/log/experimental_level/level_test.go @@ -215,9 +215,21 @@ func TestInjector(t *testing.T) { if got, want := len(output), 4; got != want { t.Errorf("missing level not injected: got len==%d, want len==%d", got, want) } + if got, want := output[0], level.Key(); got != want { + t.Errorf("wrong level key: got %#v, want %#v", got, want) + } + if got, want := output[1], level.InfoValue(); got != want { + t.Errorf("wrong level value: got %#v, want %#v", got, want) + } level.Error(logger).Log("foo", "bar") if got, want := len(output), 4; got != want { t.Errorf("leveled record modified: got len==%d, want len==%d", got, want) } + if got, want := output[0], level.Key(); got != want { + t.Errorf("wrong level key: got %#v, want %#v", got, want) + } + if got, want := output[1], level.ErrorValue(); got != want { + t.Errorf("wrong level value: got %#v, want %#v", got, want) + } } From 2755cec2f26fc32d9034353a33c8e2b70bc7a500 Mon Sep 17 00:00:00 2001 From: Chris Hines Date: Thu, 2 Mar 2017 20:07:31 -0500 Subject: [PATCH 8/8] Add clarifying sentence to NewInjector docs. --- log/experimental_level/level.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go index d36a6b1d3..9120e6161 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -124,7 +124,8 @@ func ErrNoLevel(err error) Option { } // NewInjector wraps next and returns a logger that adds a Key/level pair to -// the beginning of log events that don't already contain a level. +// the beginning of log events that don't already contain a level. In effect, +// this gives a default level to logs without a level. func NewInjector(next log.Logger, level Value) log.Logger { return &injector{ next: next,