log/alt_experimental_level: concept demonstration

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

@@ -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")
+	}
+}

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
+}

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)
+	}
+}