diff --git a/log/experimental_level/benchmark_test.go b/log/experimental_level/benchmark_test.go index 649e33de4..65b06c467 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.NewFilter(l, level.AllowInfo()) + }}, + {"AllowedLevel", func(l log.Logger) log.Logger { + return level.NewFilter(l, 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") + } + }) + } + }) + } + }) } } diff --git a/log/experimental_level/doc.go b/log/experimental_level/doc.go index 6c0055973..63a446956 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 @@ -18,10 +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. 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. +// 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/example_test.go b/log/experimental_level/example_test.go new file mode 100644 index 000000000..d18187712 --- /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.AllowInfo()) + 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..9120e6161 100644 --- a/log/experimental_level/level.go +++ b/log/experimental_level/level.go @@ -1,156 +1,205 @@ package level -import ( - "github.com/go-kit/kit/log" -) +import "github.com/go-kit/kit/log" -var ( - levelKey = "level" - errorLevelValue = "error" - warnLevelValue = "warn" - infoLevelValue = "info" - debugLevelValue = "debug" -) +// Error returns a logger that includes a Key/ErrorValue pair. +func Error(logger log.Logger) log.Logger { + return log.NewContext(logger).WithPrefix(Key(), ErrorValue()) +} -// AllowAll is an alias for AllowDebugAndAbove. -func AllowAll() []string { - return AllowDebugAndAbove() +// Warn returns a logger that includes a Key/WarnValue pair. +func Warn(logger log.Logger) log.Logger { + return log.NewContext(logger).WithPrefix(Key(), WarnValue()) } -// 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} +// Info returns a logger that includes a Key/InfoValue pair. +func Info(logger log.Logger) log.Logger { + return log.NewContext(logger).WithPrefix(Key(), InfoValue()) } -// 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} +// Debug returns a logger that includes a Key/DebugValue pair. +func Debug(logger log.Logger) log.Logger { + return log.NewContext(logger).WithPrefix(Key(), DebugValue()) } -// 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} +// 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) + } + return l } -// AllowErrorOnly allows only the default error log level. -// Its return value may be provided with the Allowed Option. -func AllowErrorOnly() []string { - return []string{errorLevelValue} +type logger struct { + next log.Logger + allowed level + squelchNoLevel bool + errNotAllowed error + errNoLevel error } -// AllowNone allows none of the default log levels. -// Its return value may be provided with the Allowed Option. -func AllowNone() []string { - return []string{} +func (l *logger) Log(keyvals ...interface{}) error { + var hasLevel, levelAllowed bool + for i := 1; i < len(keyvals); i += 2 { + if v, ok := keyvals[i].(*levelValue); ok { + hasLevel = true + levelAllowed = l.allowed&v.level != 0 + break + } + } + if !hasLevel && l.squelchNoLevel { + return l.errNoLevel + } + if hasLevel && !levelAllowed { + return l.errNotAllowed + } + return l.next.Log(keyvals...) } -// Error returns a logger with the level key set to ErrorLevelValue. -func Error(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, errorLevelValue) +// Option sets a parameter for the leveled logger. +type Option func(*logger) + +// AllowAll is an alias for AllowDebug. +func AllowAll() Option { + return AllowDebug() } -// Warn returns a logger with the level key set to WarnLevelValue. -func Warn(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, warnLevelValue) +// AllowDebug allows error, warn, info and debug level log events to pass. +func AllowDebug() Option { + return allowed(levelError | levelWarn | levelInfo | levelDebug) } -// Info returns a logger with the level key set to InfoLevelValue. -func Info(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, infoLevelValue) +// AllowInfo allows error, warn and info level log events to pass. +func AllowInfo() Option { + return allowed(levelError | levelWarn | levelInfo) } -// Debug returns a logger with the level key set to DebugLevelValue. -func Debug(logger log.Logger) log.Logger { - return log.NewContext(logger).WithPrefix(levelKey, debugLevelValue) +// AllowWarn allows error and warn level log events to pass. +func AllowWarn() Option { + return allowed(levelError | levelWarn) } -// 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{ - next: next, - } - for _, option := range options { - option(&l) - } - return &l +// 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) } -// 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) } +func allowed(allowed level) Option { + return func(l *logger) { l.allowed = 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. +// ErrNotAllowed sets the error to return from Log when it squelches a log +// 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 } } -// 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. +// 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 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. +// 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 } } -// Option sets a parameter for the leveled logger. -type Option func(*logger) +// 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. 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, + level: level, + } +} -type logger struct { - next log.Logger - allowed map[string]struct{} - errNotAllowed error - squelchNoLevel bool - errNoLevel error +type injector struct { + next log.Logger + level interface{} } -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 +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...) } - v, ok := keyvals[i+1].(string) - if !ok { - continue - } - _, levelAllowed = l.allowed[v] - break - } - if !hasLevel && l.squelchNoLevel { - return l.errNoLevel } - if hasLevel && !levelAllowed { - return l.errNotAllowed - } - 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...) } -func makeSet(a []string) map[string]struct{} { - m := make(map[string]struct{}, len(a)) - for _, s := range a { - m[s] = struct{}{} - } - return m +// 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() } + +// 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 } + +// 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 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 + +const ( + levelDebug level = 1 << iota + levelInfo + levelWarn + levelError +) + +type levelValue struct { + name string + level +} + +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 f067b43bb..047762454 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" @@ -11,11 +12,13 @@ import ( ) func TestVariousLevels(t *testing.T) { - for _, testcase := range []struct { - allowed []string + testCases := []struct { + name string + allowed level.Option want string }{ { + "AllowAll", level.AllowAll(), strings.Join([]string{ `{"level":"debug","this is":"debug log"}`, @@ -25,7 +28,8 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowDebugAndAbove(), + "AllowDebug", + level.AllowDebug(), strings.Join([]string{ `{"level":"debug","this is":"debug log"}`, `{"level":"info","this is":"info log"}`, @@ -34,7 +38,8 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowInfoAndAbove(), + "AllowDebug", + level.AllowInfo(), strings.Join([]string{ `{"level":"info","this is":"info log"}`, `{"level":"warn","this is":"warn log"}`, @@ -42,44 +47,51 @@ func TestVariousLevels(t *testing.T) { }, "\n"), }, { - level.AllowWarnAndAbove(), + "AllowWarn", + level.AllowWarn(), strings.Join([]string{ `{"level":"warn","this is":"warn log"}`, `{"level":"error","this is":"error log"}`, }, "\n"), }, { - level.AllowErrorOnly(), + "AllowError", + level.AllowError(), strings.Join([]string{ `{"level":"error","this is":"error log"}`, }, "\n"), }, { + "AllowNone", level.AllowNone(), ``, }, - } { - var buf bytes.Buffer - logger := level.New(log.NewJSONLogger(&buf), level.Allowed(testcase.allowed)) + } + + 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") + 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) + } + }) } } func TestErrNotAllowed(t *testing.T) { myError := errors.New("squelched!") opts := []level.Option{ - level.Allowed(level.AllowWarnAndAbove()), + level.AllowWarn(), 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,13 +110,13 @@ 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) } 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) } } @@ -114,13 +126,13 @@ 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) } 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) } } @@ -131,12 +143,12 @@ 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") - 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:149 foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("\nwant '%s'\nhave '%s'", want, have) } } @@ -148,10 +160,76 @@ 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 { - t.Errorf("want %q, have %q", 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) + } +} + +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) + } + }) + } +} + +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) + } + 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) } }