From b7a63435dec522c9c4f781551b342d2d3d3b0e7a Mon Sep 17 00:00:00 2001 From: "Steven E. Harris" Date: Fri, 20 Jan 2017 14:25:58 -0500 Subject: [PATCH 1/2] log/alt_experimental_level: concept demonstration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Demonstrate an alternate approach to the "level" package offered via the "github.com/go-kit/kit/log/experimental_level" import path, allowing log event level filtering via instances of the level.leveler interface, created by functions that specify the filtering threshold. Features not accommodated here for now: - Returning an error from log.Log when squelching an event - Returning an error from log.Log for events that lack a level - Documentation Benchmarks demonstrate both run time and allocation reduction for the disallowed/squelching cases compared to the "experimental_level" alternate: name old time/op new time/op delta NopBaseline-8 459ns ± 0% 130ns ± 0% -71.68% NopDisallowedLevel-8 509ns ± 0% 136ns ± 0% -73.28% NopAllowedLevel-8 515ns ± 0% 494ns ± 0% -4.08% JSONBaseline-8 2.41µs ± 0% 0.13µs ± 0% -94.45% JSONDisallowedLevel-8 506ns ± 0% 136ns ± 0% -73.12% JSONAllowedLevel-8 2.49µs ± 0% 2.45µs ± 0% -1.48% LogfmtBaseline-8 1.08µs ± 0% 0.13µs ± 0% -87.92% LogfmtDisallowedLevel-8 507ns ± 0% 136ns ± 0% -73.18% LogfmtAllowedLevel-8 1.13µs ± 0% 1.10µs ± 0% -3.26% name old alloc/op new alloc/op delta NopBaseline-8 288B ± 0% 64B ± 0% -77.78% NopDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% NopAllowedLevel-8 288B ± 0% 288B ± 0% +0.00% JSONBaseline-8 968B ± 0% 64B ± 0% -93.39% JSONDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% JSONAllowedLevel-8 968B ± 0% 968B ± 0% +0.00% LogfmtBaseline-8 288B ± 0% 64B ± 0% -77.78% LogfmtDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% LogfmtAllowedLevel-8 288B ± 0% 288B ± 0% +0.00% name old allocs/op new allocs/op delta NopBaseline-8 9.00 ± 0% 3.00 ± 0% -66.67% NopDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% NopAllowedLevel-8 9.00 ± 0% 9.00 ± 0% +0.00% JSONBaseline-8 22.0 ± 0% 3.0 ± 0% -86.36% JSONDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% JSONAllowedLevel-8 22.0 ± 0% 22.0 ± 0% +0.00% LogfmtBaseline-8 9.00 ± 0% 3.00 ± 0% -66.67% LogfmtDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% LogfmtAllowedLevel-8 9.00 ± 0% 9.00 ± 0% +0.00% --- log/alt_experimental_level/benchmark_test.go | 59 +++++++ log/alt_experimental_level/level.go | 169 +++++++++++++++++++ log/alt_experimental_level/level_test.go | 135 +++++++++++++++ 3 files changed, 363 insertions(+) create mode 100644 log/alt_experimental_level/benchmark_test.go create mode 100644 log/alt_experimental_level/level.go create mode 100644 log/alt_experimental_level/level_test.go diff --git a/log/alt_experimental_level/benchmark_test.go b/log/alt_experimental_level/benchmark_test.go new file mode 100644 index 000000000..89b015f9b --- /dev/null +++ b/log/alt_experimental_level/benchmark_test.go @@ -0,0 +1,59 @@ +package level_test + +import ( + "io/ioutil" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/alt_experimental_level" +) + +func BenchmarkNopBaseline(b *testing.B) { + benchmarkRunner(b, log.NewNopLogger()) +} + +func BenchmarkNopDisallowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingInfoAndAbove(log.NewNopLogger())) +} + +func BenchmarkNopAllowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingAll(log.NewNopLogger())) +} + +func BenchmarkJSONBaseline(b *testing.B) { + benchmarkRunner(b, log.NewJSONLogger(ioutil.Discard)) +} + +func BenchmarkJSONDisallowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingInfoAndAbove(log.NewJSONLogger(ioutil.Discard))) +} + +func BenchmarkJSONAllowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingAll(log.NewJSONLogger(ioutil.Discard))) +} + +func BenchmarkLogfmtBaseline(b *testing.B) { + benchmarkRunner(b, log.NewLogfmtLogger(ioutil.Discard)) +} + +func BenchmarkLogfmtDisallowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingInfoAndAbove(log.NewLogfmtLogger(ioutil.Discard))) +} + +func BenchmarkLogfmtAllowedLevel(b *testing.B) { + benchmarkRunner(b, + level.AllowingAll(log.NewLogfmtLogger(ioutil.Discard))) +} + +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/alt_experimental_level/level.go b/log/alt_experimental_level/level.go new file mode 100644 index 000000000..690b2f9f4 --- /dev/null +++ b/log/alt_experimental_level/level.go @@ -0,0 +1,169 @@ +package level + +import ( + "github.com/go-kit/kit/log" +) + +var ( + // Alternately, we could use a similarly inert logger that does nothing but + // return a given error value. + nop = log.NewNopLogger() +) + +type leveler interface { + Debug() log.Logger + Info() log.Logger + Warn() log.Logger + Error() log.Logger +} + +func withLevel(level string, logger log.Logger) log.Logger { + return log.NewContext(logger).With("level", level) +} + +type debugAndAbove struct { + log.Logger +} + +func (l debugAndAbove) Debug() log.Logger { + return withLevel("debug", l.Logger) +} + +func (l debugAndAbove) Info() log.Logger { + return withLevel("info", l.Logger) +} + +func (l debugAndAbove) Warn() log.Logger { + return withLevel("warn", l.Logger) +} + +func (l debugAndAbove) Error() log.Logger { + return withLevel("error", l.Logger) +} + +type infoAndAbove struct { + debugAndAbove +} + +func (infoAndAbove) Debug() log.Logger { + return nop +} + +type warnAndAbove struct { + infoAndAbove +} + +func (warnAndAbove) Info() log.Logger { + return nop +} + +type errorOnly struct { + warnAndAbove +} + +func (errorOnly) Warn() log.Logger { + return nop +} + +type none struct { + errorOnly +} + +func (none) Error() log.Logger { + return nop +} + +func AllowingAll(logger log.Logger) log.Logger { + return AllowingDebugAndAbove(logger) +} + +func AllowingDebugAndAbove(logger log.Logger) log.Logger { + if _, ok := logger.(leveler); ok { + return logger + } + return debugAndAbove{logger} +} + +func AllowingInfoAndAbove(logger log.Logger) log.Logger { + switch l := logger.(type) { + case debugAndAbove: + return infoAndAbove{l} + case infoAndAbove, warnAndAbove, errorOnly, none: + return logger + default: + return infoAndAbove{debugAndAbove{logger}} + } +} + +func AllowingWarnAndAbove(logger log.Logger) log.Logger { + switch l := logger.(type) { + case debugAndAbove: + return warnAndAbove{infoAndAbove{l}} + case infoAndAbove: + return warnAndAbove{l} + case warnAndAbove, errorOnly, none: + return logger + default: + return warnAndAbove{infoAndAbove{debugAndAbove{logger}}} + } +} + +func AllowingErrorOnly(logger log.Logger) log.Logger { + switch l := logger.(type) { + case debugAndAbove: + return errorOnly{warnAndAbove{infoAndAbove{l}}} + case infoAndAbove: + return errorOnly{warnAndAbove{l}} + case warnAndAbove: + return errorOnly{l} + case errorOnly, none: + return logger + default: + return errorOnly{warnAndAbove{infoAndAbove{debugAndAbove{logger}}}} + } +} + +func AllowingNone(logger log.Logger) log.Logger { + switch l := logger.(type) { + case debugAndAbove: + return none{errorOnly{warnAndAbove{infoAndAbove{l}}}} + case infoAndAbove: + return none{errorOnly{warnAndAbove{l}}} + case warnAndAbove: + return none{errorOnly{l}} + case errorOnly: + return none{l} + case none: + return logger + default: + return none{errorOnly{warnAndAbove{infoAndAbove{debugAndAbove{logger}}}}} + } +} + +func Debug(logger log.Logger) log.Logger { + if l, ok := logger.(leveler); ok { + return l.Debug() + } + return nop +} + +func Info(logger log.Logger) log.Logger { + if l, ok := logger.(leveler); ok { + return l.Info() + } + return nop +} + +func Warn(logger log.Logger) log.Logger { + if l, ok := logger.(leveler); ok { + return l.Warn() + } + return nop +} + +func Error(logger log.Logger) log.Logger { + if l, ok := logger.(leveler); ok { + return l.Error() + } + return nop +} diff --git a/log/alt_experimental_level/level_test.go b/log/alt_experimental_level/level_test.go new file mode 100644 index 000000000..b1cafa4d5 --- /dev/null +++ b/log/alt_experimental_level/level_test.go @@ -0,0 +1,135 @@ +package level_test + +import ( + "bytes" + "strings" + "testing" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/alt_experimental_level" +) + +func TestInstanceLevels(t *testing.T) { + for _, testcase := range []struct { + allowed string + allow func(log.Logger) log.Logger + want string + }{ + { + "all", + level.AllowingAll, + 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"), + }, + { + "debug+", + level.AllowingDebugAndAbove, + 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"), + }, + { + "info+", + level.AllowingInfoAndAbove, + strings.Join([]string{ + `{"level":"info","this is":"info log"}`, + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "warn+", + level.AllowingWarnAndAbove, + strings.Join([]string{ + `{"level":"warn","this is":"warn log"}`, + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "error", + level.AllowingErrorOnly, + strings.Join([]string{ + `{"level":"error","this is":"error log"}`, + }, "\n"), + }, + { + "none", + level.AllowingNone, + ``, + }, + } { + var buf bytes.Buffer + logger := testcase.allow(log.NewJSONLogger(&buf)) + + 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=%s: want\n%s\nhave\n%s", testcase.allowed, 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.AllowingAll(logger) + logger = level.Info(logger) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + logger.Log("foo", "bar") + if want, have := `level=info caller=level_test.go:93 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 allows users to use + // log.DefaultCaller as per normal. + var logger log.Logger + logger = log.NewLogfmtLogger(&buf) + logger = log.NewContext(logger).With("caller", log.DefaultCaller) + + logger = level.AllowingAll(logger) + level.Info(logger).Log("foo", "bar") + if want, have := `caller=level_test.go:109 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} + +func TestMoreRestrictiveLevelLayering(t *testing.T) { + var buf bytes.Buffer + logger := log.NewJSONLogger(&buf) + logger = level.AllowingAll(logger) + logger = level.AllowingInfoAndAbove(logger) + level.Debug(logger).Log("this is", "debug log") + if want, have := "", strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} + +func TestLessRestrictiveLevelLayering(t *testing.T) { + var buf bytes.Buffer + logger := log.NewJSONLogger(&buf) + logger = level.AllowingInfoAndAbove(logger) + logger = level.AllowingAll(logger) + level.Debug(logger).Log("this is", "debug log") + if want, have := "", strings.TrimSpace(buf.String()); want != have { + t.Errorf("want %q, have %q", want, have) + } +} From c6bd2a97fc2ac05fc18a1aa20d32c55e9276f86b Mon Sep 17 00:00:00 2001 From: "Steven E. Harris" Date: Mon, 30 Jan 2017 16:48:29 -0500 Subject: [PATCH 2/2] Accommodate wrapped Logger instances MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Introduce the "log.Delegate" function to extract a wrapped delegate Logger instance from a decorating instance, allowing the level-related functions to find the configuration they need within the outermost Logger created by one of the leveled factory functions. Benchmarks demonstrate both run time and allocation reduction for the disallowed/squelching cases compared to the "experimental_level" alternate: name old time/op new time/op delta NopBaseline-8 470ns ± 0% 494ns ± 0% +5.11% NopDisallowedLevel-8 513ns ± 0% 123ns ± 0% -76.02% NopAllowedLevel-8 516ns ± 0% 474ns ± 0% -8.14% JSONBaseline-8 2.44µs ± 0% 2.39µs ± 0% -2.45% JSONDisallowedLevel-8 515ns ± 0% 123ns ± 0% -76.12% JSONAllowedLevel-8 2.48µs ± 0% 2.33µs ± 0% -5.97% LogfmtBaseline-8 1.05µs ± 0% 1.03µs ± 0% -2.19% LogfmtDisallowedLevel-8 514ns ± 0% 121ns ± 0% -76.46% LogfmtAllowedLevel-8 1.13µs ± 0% 1.02µs ± 0% -9.39% name old alloc/op new alloc/op delta NopBaseline-8 288B ± 0% 288B ± 0% +0.00% NopDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% NopAllowedLevel-8 288B ± 0% 288B ± 0% +0.00% JSONBaseline-8 968B ± 0% 968B ± 0% +0.00% JSONDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% JSONAllowedLevel-8 968B ± 0% 968B ± 0% +0.00% LogfmtBaseline-8 288B ± 0% 288B ± 0% +0.00% LogfmtDisallowedLevel-8 288B ± 0% 64B ± 0% -77.78% LogfmtAllowedLevel-8 288B ± 0% 288B ± 0% +0.00% name old allocs/op new allocs/op delta NopBaseline-8 9.00 ± 0% 9.00 ± 0% +0.00% NopDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% NopAllowedLevel-8 9.00 ± 0% 9.00 ± 0% +0.00% JSONBaseline-8 22.0 ± 0% 22.0 ± 0% +0.00% JSONDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% JSONAllowedLevel-8 22.0 ± 0% 22.0 ± 0% +0.00% LogfmtBaseline-8 9.00 ± 0% 9.00 ± 0% +0.00% LogfmtDisallowedLevel-8 9.00 ± 0% 3.00 ± 0% -66.67% LogfmtAllowedLevel-8 9.00 ± 0% 9.00 ± 0% +0.00% The running time increase in the "NopBaseline-8" benchmare is due to the level.Debug function doing more work, needing to inspect the supplied log.Logger to see whether it wraps a level restriction that would preclude preceding with creating a log.Context to record the level. --- log/alt_experimental_level/level.go | 195 ++++++++++++++--------- log/alt_experimental_level/level_test.go | 136 +++++++++++++--- log/log.go | 26 +++ log/log_test.go | 26 +++ 4 files changed, 285 insertions(+), 98 deletions(-) diff --git a/log/alt_experimental_level/level.go b/log/alt_experimental_level/level.go index 690b2f9f4..cbe419204 100644 --- a/log/alt_experimental_level/level.go +++ b/log/alt_experimental_level/level.go @@ -1,20 +1,86 @@ package level -import ( - "github.com/go-kit/kit/log" -) +import "github.com/go-kit/kit/log" var ( // Alternately, we could use a similarly inert logger that does nothing but // return a given error value. nop = log.NewNopLogger() + + // Invoking a leveling function with a Logger that neither + // originated from nor wraps a Logger that originated from one of + // the level-filtering factory functions still yields a + // level-stamped Context, as if no filtering is in effect. + defaultLeveler = &debugAndAbove{} ) type leveler interface { - Debug() log.Logger - Info() log.Logger - Warn() log.Logger - Error() log.Logger + Debug(log.Logger) log.Logger + Info(log.Logger) log.Logger + Warn(log.Logger) log.Logger + Error(log.Logger) log.Logger +} + +type leveledLogger struct { + log.Logger + leveler +} + +func outermostLevelerOr(logger log.Logger, otherwise leveler) leveler { + for { + switch l := logger.(type) { + case *leveledLogger: + return l.leveler + // Optimize unwrapping a Context by saving a type comparison. + case *log.Context: + logger = l.Delegate() + default: + logger = log.Delegate(logger) + } + if logger == nil { + return otherwise + } + } +} + +func outermostLeveler(logger log.Logger) leveler { + return outermostLevelerOr(logger, nil) +} + +func outermostEffectiveLeveler(logger log.Logger) leveler { + return outermostLevelerOr(logger, defaultLeveler) +} + +// Debug returns a logger ready to emit log records at the "debug" +// level, intended for fine-level detailed tracing information. If the +// supplied logger disallows records at that level, it instead returns +// an inert logger that drops the record. +func Debug(logger log.Logger) log.Logger { + return outermostEffectiveLeveler(logger).Debug(logger) +} + +// Info returns a logger ready to emit log records at the "info" +// level, intended for informational messages. If the supplied logger +// disallows records at that level, it instead returns an inert logger +// that drops the record. +func Info(logger log.Logger) log.Logger { + return outermostEffectiveLeveler(logger).Info(logger) +} + +// Warn returns a logger ready to emit log records at the "warn" +// level, intended for indicating potential problems. If the supplied +// logger disallows records at that level, it instead returns an inert +// logger that drops the record. +func Warn(logger log.Logger) log.Logger { + return outermostEffectiveLeveler(logger).Warn(logger) +} + +// Error returns a logger ready to emit log records at the "error" +// level, intended for indicating serious failures. If the supplied +// logger disallows records at that level, it instead returns an inert +// logger that drops the record. +func Error(logger log.Logger) log.Logger { + return outermostEffectiveLeveler(logger).Error(logger) } func withLevel(level string, logger log.Logger) log.Logger { @@ -22,30 +88,29 @@ func withLevel(level string, logger log.Logger) log.Logger { } type debugAndAbove struct { - log.Logger } -func (l debugAndAbove) Debug() log.Logger { - return withLevel("debug", l.Logger) +func (l debugAndAbove) Debug(logger log.Logger) log.Logger { + return withLevel("debug", logger) } -func (l debugAndAbove) Info() log.Logger { - return withLevel("info", l.Logger) +func (l debugAndAbove) Info(logger log.Logger) log.Logger { + return withLevel("info", logger) } -func (l debugAndAbove) Warn() log.Logger { - return withLevel("warn", l.Logger) +func (l debugAndAbove) Warn(logger log.Logger) log.Logger { + return withLevel("warn", logger) } -func (l debugAndAbove) Error() log.Logger { - return withLevel("error", l.Logger) +func (l debugAndAbove) Error(logger log.Logger) log.Logger { + return withLevel("error", logger) } type infoAndAbove struct { debugAndAbove } -func (infoAndAbove) Debug() log.Logger { +func (infoAndAbove) Debug(logger log.Logger) log.Logger { return nop } @@ -53,7 +118,7 @@ type warnAndAbove struct { infoAndAbove } -func (warnAndAbove) Info() log.Logger { +func (warnAndAbove) Info(logger log.Logger) log.Logger { return nop } @@ -61,7 +126,7 @@ type errorOnly struct { warnAndAbove } -func (errorOnly) Warn() log.Logger { +func (errorOnly) Warn(logger log.Logger) log.Logger { return nop } @@ -69,101 +134,75 @@ type none struct { errorOnly } -func (none) Error() log.Logger { +func (none) Error(logger log.Logger) log.Logger { return nop } +// AllowingAll returns a logger allowed to emit log records at all +// levels, unless the supplied logger is already restricted to some +// narrower set of levels, in which case it retains that restriction. +// +// The behavior is equivalent to AllowingDebugAndAbove. func AllowingAll(logger log.Logger) log.Logger { return AllowingDebugAndAbove(logger) } +// AllowingDebugAndAbove returns a logger allowed to emit log records +// at all levels, unless the supplied logger is already restricted to +// some narrower set of levels, in which case it retains that +// restriction. func AllowingDebugAndAbove(logger log.Logger) log.Logger { - if _, ok := logger.(leveler); ok { + if outermostLeveler(logger) != nil { return logger } - return debugAndAbove{logger} + return &leveledLogger{logger, debugAndAbove{}} } +// AllowingInfoAndAbove returns a logger allowed to emit log records +// at levels "info" and above, dropping "debug"-level records, unless +// the supplied logger is already restricted to some narrower set of +// levels, in which case it retains that restriction. func AllowingInfoAndAbove(logger log.Logger) log.Logger { - switch l := logger.(type) { - case debugAndAbove: - return infoAndAbove{l} + switch outermostLeveler(logger).(type) { case infoAndAbove, warnAndAbove, errorOnly, none: return logger default: - return infoAndAbove{debugAndAbove{logger}} + return &leveledLogger{logger, infoAndAbove{}} } } +// AllowingWarnAndAbove returns a logger allowed to emit log records +// at levels "warn" and above, dropping "debug"- and "info"-level +// records, unless the supplied logger is already restricted to some +// narrower set of levels, in which case it retains that restriction. func AllowingWarnAndAbove(logger log.Logger) log.Logger { - switch l := logger.(type) { - case debugAndAbove: - return warnAndAbove{infoAndAbove{l}} - case infoAndAbove: - return warnAndAbove{l} + switch outermostLeveler(logger).(type) { case warnAndAbove, errorOnly, none: return logger default: - return warnAndAbove{infoAndAbove{debugAndAbove{logger}}} + return &leveledLogger{logger, warnAndAbove{}} } } +// AllowingErrorOnly returns a logger allowed to emit log records only +// at level "error", dropping "debug"-, "info"-, and "warn"-level +// records, unless the supplied logger is already restricted to some +// narrower set of levels, in which case it retains that restriction. func AllowingErrorOnly(logger log.Logger) log.Logger { - switch l := logger.(type) { - case debugAndAbove: - return errorOnly{warnAndAbove{infoAndAbove{l}}} - case infoAndAbove: - return errorOnly{warnAndAbove{l}} - case warnAndAbove: - return errorOnly{l} + switch outermostLeveler(logger).(type) { case errorOnly, none: return logger default: - return errorOnly{warnAndAbove{infoAndAbove{debugAndAbove{logger}}}} + return &leveledLogger{logger, errorOnly{}} } } +// AllowingNone returns a logger that drops log records at all levels. func AllowingNone(logger log.Logger) log.Logger { - switch l := logger.(type) { - case debugAndAbove: - return none{errorOnly{warnAndAbove{infoAndAbove{l}}}} - case infoAndAbove: - return none{errorOnly{warnAndAbove{l}}} - case warnAndAbove: - return none{errorOnly{l}} - case errorOnly: - return none{l} + switch outermostLeveler(logger).(type) { case none: return logger default: - return none{errorOnly{warnAndAbove{infoAndAbove{debugAndAbove{logger}}}}} - } -} - -func Debug(logger log.Logger) log.Logger { - if l, ok := logger.(leveler); ok { - return l.Debug() + return &leveledLogger{logger, none{}} } - return nop -} - -func Info(logger log.Logger) log.Logger { - if l, ok := logger.(leveler); ok { - return l.Info() - } - return nop -} - -func Warn(logger log.Logger) log.Logger { - if l, ok := logger.(leveler); ok { - return l.Warn() - } - return nop -} - -func Error(logger log.Logger) log.Logger { - if l, ok := logger.(leveler); ok { - return l.Error() - } - return nop } diff --git a/log/alt_experimental_level/level_test.go b/log/alt_experimental_level/level_test.go index b1cafa4d5..0a9eb906b 100644 --- a/log/alt_experimental_level/level_test.go +++ b/log/alt_experimental_level/level_test.go @@ -99,11 +99,11 @@ func TestLevelContext(t *testing.T) { func TestContextLevel(t *testing.T) { var buf bytes.Buffer - // Wrapping a context with the level logger allows users to use - // log.DefaultCaller as per normal. + // 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.DefaultCaller) + logger = log.NewContext(logger).With("caller", log.Caller(5)) logger = level.AllowingAll(logger) level.Info(logger).Log("foo", "bar") @@ -112,24 +112,120 @@ func TestContextLevel(t *testing.T) { } } -func TestMoreRestrictiveLevelLayering(t *testing.T) { - var buf bytes.Buffer - logger := log.NewJSONLogger(&buf) - logger = level.AllowingAll(logger) - logger = level.AllowingInfoAndAbove(logger) - level.Debug(logger).Log("this is", "debug log") - if want, have := "", strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) +func TestLevelLayerRestrictions(t *testing.T) { + factories := []struct { + name string + f func(log.Logger) log.Logger + }{ + {"all", level.AllowingAll}, + {"debug+", level.AllowingDebugAndAbove}, + {"info+", level.AllowingInfoAndAbove}, + {"warn+", level.AllowingWarnAndAbove}, + {"error", level.AllowingErrorOnly}, + {"none", level.AllowingNone}, + } + emitters := []struct { + name string + f func(log.Logger) log.Logger + }{ + {"debug", level.Debug}, + {"info", level.Info}, + {"warn", level.Warn}, + {"error", level.Error}, + } + tests := [][][4]bool{ + // all + { + {true, true, true, true}, // all + {true, true, true, true}, // debug+ + {false, true, true, true}, // info+ + {false, false, true, true}, // warn+ + {false, false, false, true}, // error + {false, false, false, false}, // none + }, + // debug+ + { + {true, true, true, true}, // all + {true, true, true, true}, // debug+ + {false, true, true, true}, // info+ + {false, false, true, true}, // warn+ + {false, false, false, true}, // error + {false, false, false, false}, // none + }, + // info+ + { + {false, true, true, true}, // all + {false, true, true, true}, // debug+ + {false, true, true, true}, // info+ + {false, false, true, true}, // warn+ + {false, false, false, true}, // error + {false, false, false, false}, // none + }, + // warn+ + { + {false, false, true, true}, // all + {false, false, true, true}, // debug+ + {false, false, true, true}, // info+ + {false, false, true, true}, // warn+ + {false, false, false, true}, // error + {false, false, false, false}, // none + }, + // error + { + {false, false, false, true}, // all + {false, false, false, true}, // debug+ + {false, false, false, true}, // info+ + {false, false, false, true}, // warn+ + {false, false, false, true}, // error + {false, false, false, false}, // none + }, + // none + { + {false, false, false, false}, // all + {false, false, false, false}, // debug+ + {false, false, false, false}, // info+ + {false, false, false, false}, // warn+ + {false, false, false, false}, // error + {false, false, false, false}, // none + }, } -} - -func TestLessRestrictiveLevelLayering(t *testing.T) { var buf bytes.Buffer - logger := log.NewJSONLogger(&buf) - logger = level.AllowingInfoAndAbove(logger) - logger = level.AllowingAll(logger) - level.Debug(logger).Log("this is", "debug log") - if want, have := "", strings.TrimSpace(buf.String()); want != have { - t.Errorf("want %q, have %q", want, have) + logger := log.NewLogfmtLogger(&buf) + for i, test := range tests { + t.Run(factories[i].name, func(t *testing.T) { + initialLogger := factories[i].f(logger) + if initialLogger == nil { + t.Fatal("initial factory returned nil") + } + // Wrap with an intervening layer to confirm that + // subsequent level restricting factories can see through + // to the inner restriction. + initialLogger = log.NewContext(initialLogger) + for j, layer := range test { + t.Run(factories[j].name, func(t *testing.T) { + layeredLogger := factories[j].f(initialLogger) + if layeredLogger == nil { + t.Fatal("layering factory returned nil") + } + for k, expected := range layer { + t.Run(emitters[k].name, func(t *testing.T) { + defer buf.Reset() + leveled := emitters[k].f(layeredLogger) + if leveled == nil { + t.Fatalf("leveled emitter function returned nil") + } + leveled.Log("m", "x") + if buf.Len() > 0 { + if !expected { + t.Fatalf("want no output, have %q", buf.Bytes()) + } + } else if expected { + t.Fatal("want output, have none") + } + }) + } + }) + } + }) } } diff --git a/log/log.go b/log/log.go index 97990feff..56cd1029f 100644 --- a/log/log.go +++ b/log/log.go @@ -11,6 +11,27 @@ type Logger interface { Log(keyvals ...interface{}) error } +// Delegate returns the Logger to which the supplied Logger delegates, +// if any. A logger has a discoverable delegate if it implements the +// following interface: +// +// type delegator interface { +// Delegate() Logger +// } +// +// If the Logger is nil or does not implement Delegate, it returns +// nil. +func Delegate(logger Logger) Logger { + type delegator interface { + Delegate() Logger + } + + if decorator, ok := logger.(delegator); ok { + return decorator.Delegate() + } + return nil +} + // ErrMissingValue is appended to keyvals slices with odd length to substitute // the missing value. var ErrMissingValue = errors.New("(MISSING)") @@ -133,6 +154,11 @@ func (l *Context) WithPrefix(keyvals ...interface{}) *Context { } } +// Delegate returns the Logger wrapped by the receiver. +func (l *Context) Delegate() Logger { + return l.logger +} + // LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If // f is a function with the appropriate signature, LoggerFunc(f) is a Logger // object that calls f. diff --git a/log/log_test.go b/log/log_test.go index 7c44095b3..3884f610a 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -120,6 +120,32 @@ func TestContextStackDepth(t *testing.T) { } } +func TestWrappedLoggerDelegation(t *testing.T) { + var buf bytes.Buffer + inner := log.NewLogfmtLogger(&buf) + outer := log.NewContext(inner) + tests := []struct { + description string + delegate log.Logger + }{ + {"Context.Delegate", outer.Delegate()}, + {"log.Delegate", log.Delegate(outer)}, + } + for _, test := range tests { + t.Run(test.description, func(t *testing.T) { + if test.delegate != inner { + if test.delegate == nil { + t.Fatal("have nil, want inner logger") + } else if test.delegate == outer { + t.Fatal("have self, want inner logger") + } else { + t.Fatal("have unknown logger, want inner logger") + } + } + }) + } +} + // Test that With returns a Logger safe for concurrent use. This test // validates that the stored logging context does not get corrupted when // multiple clients concurrently log additional keyvals.