diff --git a/log/experimental_level/benchmark_test.go b/log/experimental_level/benchmark_test.go new file mode 100644 index 000000000..176af248d --- /dev/null +++ b/log/experimental_level/benchmark_test.go @@ -0,0 +1,65 @@ +package level_test + +import ( + "io/ioutil" + "testing" + + "github.com/go-kit/kit/log" + "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.Config{ + Allowed: level.AllowInfoAndAbove(), + })) +} + +func BenchmarkNopAllowedLevel(b *testing.B) { + benchmarkRunner(b, level.New(log.NewNopLogger(), level.Config{ + 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.Config{ + Allowed: level.AllowInfoAndAbove(), + })) +} + +func BenchmarkJSONAllowedLevel(b *testing.B) { + benchmarkRunner(b, level.New(log.NewJSONLogger(ioutil.Discard), level.Config{ + Allowed: level.AllowAll(), + })) +} + +func BenchmarkLogfmtBaseline(b *testing.B) { + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) +} + +func BenchmarkLogfmtDisallowedLevel(b *testing.B) { + benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), level.Config{ + Allowed: level.AllowInfoAndAbove(), + })) +} + +func BenchmarkLogfmtAllowedLevel(b *testing.B) { + benchmarkRunner(b, level.New(log.NewLogfmtLogger(ioutil.Discard), level.Config{ + 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") + } +} diff --git a/log/experimental_level/doc.go b/log/experimental_level/doc.go new file mode 100644 index 000000000..7b81a9756 --- /dev/null +++ b/log/experimental_level/doc.go @@ -0,0 +1,27 @@ +// Package level is an EXPERIMENTAL levelled logging package. The API will +// 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. +// +// var logger log.Logger +// logger = log.NewLogfmtLogger(os.Stderr) +// logger = level.New(logger, level.Config{Allowed: level.AllowInfoAndAbove}) // <-- +// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC) +// +// Then, at the callsites, use one of the level.Debug, Info, Warn, or Error +// helper methods to emit leveled log events. +// +// logger.Log("foo", "bar") // as normal, no level +// level.Debug(logger).Log("request_id", reqID, "trace_data", trace.Get()) +// if value > 100 { +// 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 Config struct 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 Config struct, and write your own level.Foo-style +// helper methods. +package level diff --git a/log/experimental_level/level.go b/log/experimental_level/level.go new file mode 100644 index 000000000..6210d5c14 --- /dev/null +++ b/log/experimental_level/level.go @@ -0,0 +1,146 @@ +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 as the Allowed parameter in the Config. +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 as the Allowed parameter in the Config. +func AllowInfoAndAbove() []string { + return []string{errorLevelValue, warnLevelValue, infoLevelValue} +} + +// AllowWarnAndAbove allows the default warn and error log levels. +// Its return value may be provided as the Allowed parameter in the Config. +func AllowWarnAndAbove() []string { + return []string{errorLevelValue, warnLevelValue} +} + +// AllowErrorOnly allows only the default error log level. +// Its return value may be provided as the Allowed parameter in the Config. +func AllowErrorOnly() []string { + return []string{errorLevelValue} +} + +// AllowNone allows none of the default log levels. +// Its return value may be provided as the Allowed parameter in the Config. +func AllowNone() []string { + return []string{} +} + +// Error returns a logger with the level key set to ErrorLevelValue. +func Error(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, errorLevelValue) +} + +// Warn returns a logger with the level key set to WarnLevelValue. +func Warn(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, warnLevelValue) +} + +// Info returns a logger with the level key set to InfoLevelValue. +func Info(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, infoLevelValue) +} + +// Debug returns a logger with the level key set to DebugLevelValue. +func Debug(logger log.Logger) log.Logger { + return log.NewContext(logger).With(levelKey, debugLevelValue) +} + +// Config parameterizes the leveled logger. +type Config struct { + // 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. + Allowed []string + + // ErrNotAllowed is returned to the caller when Log is invoked with a level + // key that hasn't been explicitly allowed. By default, ErrNotAllowed is + // nil; in this case, the log event is squelched with no error. + ErrNotAllowed error + + // 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 bool + + // 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 error +} + +// New wraps the logger and implements level checking. See the commentary on the +// Config object for a detailed description of how to configure levels. +func New(next log.Logger, config Config) log.Logger { + return &logger{ + next: next, + allowed: makeSet(config.Allowed), + errNotAllowed: config.ErrNotAllowed, + squelchNoLevel: config.SquelchNoLevel, + errNoLevel: config.ErrNoLevel, + } +} + +type logger struct { + next log.Logger + allowed map[string]struct{} + errNotAllowed error + squelchNoLevel bool + 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 + } + 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...) +} + +func makeSet(a []string) map[string]struct{} { + m := make(map[string]struct{}, len(a)) + for _, s := range a { + m[s] = struct{}{} + } + return m +} diff --git a/log/experimental_level/level_test.go b/log/experimental_level/level_test.go new file mode 100644 index 000000000..741d3980c --- /dev/null +++ b/log/experimental_level/level_test.go @@ -0,0 +1,154 @@ +package level_test + +import ( + "bytes" + "errors" + "strings" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/experimental_level" +) + +func TestVariousLevels(t *testing.T) { + for _, testcase := range []struct { + allowed []string + want string + }{ + { + level.AllowAll(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + level.AllowDebugAndAbove(), + strings.Join([]string{ + `{"level":"debug","this is":"debug log"}`, + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + level.AllowInfoAndAbove(), + strings.Join([]string{ + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + level.AllowWarnAndAbove(), + strings.Join([]string{ + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + level.AllowErrorOnly(), + strings.Join([]string{ + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + level.AllowNone(), + ``, + }, + } { + var buf bytes.Buffer + logger := level.New(log.NewJSONLogger(&buf), level.Config{Allowed: 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") + + 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) + } + } +} + +func TestErrNotAllowed(t *testing.T) { + myError := errors.New("squelched!") + logger := level.New(log.NewNopLogger(), level.Config{ + Allowed: level.AllowWarnAndAbove(), + ErrNotAllowed: myError, + }) + + if want, have := myError, level.Info(logger).Log("foo", "bar"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } + + if want, have := error(nil), level.Warn(logger).Log("foo", "bar"); want != have { + t.Errorf("want %#+v, have %#+v", want, have) + } +} + +func TestErrNoLevel(t *testing.T) { + myError := errors.New("no level specified") + + var buf bytes.Buffer + logger := level.New(log.NewJSONLogger(&buf), level.Config{ + SquelchNoLevel: true, + ErrNoLevel: myError, + }) + + 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) + } +} + +func TestAllowNoLevel(t *testing.T) { + var buf bytes.Buffer + logger := level.New(log.NewJSONLogger(&buf), level.Config{ + SquelchNoLevel: false, + ErrNoLevel: errors.New("I should never be returned!"), + }) + + 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) + } +} + +func TestLevelContext(t *testing.T) { + var buf bytes.Buffer + + // Wrapping the level logger with a context allows users to use + // log.DefaultCaller as per normal. + var logger log.Logger + logger = log.NewLogfmtLogger(&buf) + logger = level.New(logger, level.Config{Allowed: level.AllowAll()}) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + level.Info(logger).Log("foo", "bar") + if want, have := `caller=level_test.go:134 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} + +func TestContextLevel(t *testing.T) { + var buf bytes.Buffer + + // Wrapping a context with the level logger still works, but requires users + // to specify a higher callstack depth value. + var logger log.Logger + logger = log.NewLogfmtLogger(&buf) + logger = log.NewContext(logger).With("caller", log.Caller(5)) + logger = level.New(logger, level.Config{Allowed: level.AllowAll()}) + + level.Info(logger).Log("foo", "bar") + if want, have := `caller=level_test.go:150 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} diff --git a/log/nop_logger_test.go b/log/nop_logger_test.go index 25af1836d..70e69cdfe 100644 --- a/log/nop_logger_test.go +++ b/log/nop_logger_test.go @@ -16,3 +16,11 @@ func TestNopLogger(t *testing.T) { t.Error(err) } } + +func BenchmarkNopLoggerSimple(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger(), baseMessage) +} + +func BenchmarkNopLoggerContextual(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger(), withMessage) +}