From e3d5e91904b9776dd21c59afa2e0503c09098a2f Mon Sep 17 00:00:00 2001 From: Vinay P Date: Fri, 12 Jun 2020 13:29:49 +0100 Subject: [PATCH] log.WithSuffix, appends kvs to those passed to Log enhancement suggested in: https://github.com/go-kit/kit/issues/991 why? if a human is reading logfmt output on the shell or in the web browser, it helps to have certain fields prefixed, e.g. ts, but certain fields are better suffixed, e.g. caller, environment, so that more important information appears first. benchmarks suggest an additional cost only if WithSuffix is used. goos: darwin goarch: amd64 pkg: github.com/go-kit/kit/log BenchmarkDiscard-4 32230156 38 ns/op 32 B/op 1 allocs/op BenchmarkOneWith-4 9647907 122 ns/op 96 B/op 2 allocs/op BenchmarkTwoWith-4 8935790 134 ns/op 160 B/op 2 allocs/op BenchmarkTenWith-4 5016836 236 ns/op 672 B/op 2 allocs/op BenchmarkOneWithPrefix-4 9907198 123 ns/op 96 B/op 2 allocs/op BenchmarkTenWithPrefix-4 5076309 239 ns/op 672 B/op 2 allocs/op BenchmarkOneWithSuffix-4 6432942 189 ns/op 128 B/op 3 allocs/op BenchmarkTenWithSuffix-4 4899711 246 ns/op 416 B/op 3 allocs/op BenchmarkOneWithPrefixSuffix-4 6111750 197 ns/op 160 B/op 3 allocs/op BenchmarkTenWithPrefixSuffix-4 2172066 555 ns/op 1952 B/op 3 allocs/op PASS ok github.com/go-kit/kit/log 14.224s --- log/log.go | 62 ++++++++++++++++--- log/log_test.go | 158 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 211 insertions(+), 9 deletions(-) diff --git a/log/log.go b/log/log.go index 66a9e2fde..4c0af6e7d 100644 --- a/log/log.go +++ b/log/log.go @@ -36,8 +36,10 @@ func With(logger Logger, keyvals ...interface{}) Logger { // backing array is created if the slice must grow in Log or With. // Using the extra capacity without copying risks a data race that // would violate the Logger interface contract. - keyvals: kvs[:len(kvs):len(kvs)], - hasValuer: l.hasValuer || containsValuer(keyvals), + keyvals: kvs[:len(kvs):len(kvs)], + hasValuer: l.hasValuer || containsValuer(keyvals), + sKeyvals: l.sKeyvals, + sHasValuer: l.sHasValuer, } } @@ -67,9 +69,45 @@ func WithPrefix(logger Logger, keyvals ...interface{}) Logger { } kvs = append(kvs, l.keyvals...) return &context{ - logger: l.logger, - keyvals: kvs, - hasValuer: l.hasValuer || containsValuer(keyvals), + logger: l.logger, + keyvals: kvs, + hasValuer: l.hasValuer || containsValuer(keyvals), + sKeyvals: l.sKeyvals, + sHasValuer: l.sHasValuer, + } +} + +// WithSuffix returns a new contextual logger with keyvals appended to those +// passed to calls to Log. If logger is also a contextual logger, keyvals is +// appended to the existing context. +// +// The returned Logger replaces all value elements (odd indexes) containing a +// Valuer with their generated value for each call to its Log method. +func WithSuffix(logger Logger, keyvals ...interface{}) Logger { + if len(keyvals) == 0 { + return logger + } + l := newContext(logger) + // Limiting the capacity of the stored keyvals ensures that a new + // backing array is created if the slice must grow in Log or With. + // Using the extra capacity without copying risks a data race that + // would violate the Logger interface contract. + n := len(l.sKeyvals) + len(keyvals) + if len(keyvals)%2 != 0 { + n++ + } + kvs := make([]interface{}, 0, n) + kvs = append(kvs, keyvals...) + if len(kvs)%2 != 0 { + kvs = append(kvs, ErrMissingValue) + } + kvs = append(l.sKeyvals, kvs...) + return &context{ + logger: l.logger, + keyvals: l.keyvals, + hasValuer: l.hasValuer, + sKeyvals: kvs, + sHasValuer: l.sHasValuer || containsValuer(keyvals), } } @@ -93,9 +131,11 @@ func WithPrefix(logger Logger, keyvals ...interface{}) Logger { // returning a newly constructed context with a merged keyvals rather // than simply wrapping the existing context. type context struct { - logger Logger - keyvals []interface{} - hasValuer bool + logger Logger + keyvals []interface{} + sKeyvals []interface{} // suffixes + hasValuer bool + sHasValuer bool } func newContext(logger Logger) *context { @@ -119,7 +159,11 @@ func (l *context) Log(keyvals ...interface{}) error { if len(keyvals) == 0 { kvs = append([]interface{}{}, l.keyvals...) } - bindValues(kvs[:len(l.keyvals)]) + bindValues(kvs[:(len(l.keyvals))]) + } + kvs = append(kvs, l.sKeyvals...) + if l.sHasValuer { + bindValues(kvs[len(kvs) - len(l.sKeyvals):]) } return l.logger.Log(kvs...) } diff --git a/log/log_test.go b/log/log_test.go index 1bf29727e..39c4a8b6d 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -56,6 +56,55 @@ func TestContextMissingValue(t *testing.T) { } } +func TestWithPrefixAndSuffix(t *testing.T) { + t.Parallel() + var output []interface{} + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + lc := log.WithPrefix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := 6, len(output); want != have { + t.Errorf("want len(output) == %v, have %v", want, have) + } + want := []string{"a", "first", "msg", "message", "z", "last"} + for i := 0; i < 6; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } + + lc = log.With(logger, "b", "second") + lc = log.WithPrefix(lc, "a", "first") + lc = log.With(lc, "c", "third") + lc = log.WithSuffix(lc, "z", "last") + lc = log.WithSuffix(lc, "aa", "sequel") + if err := lc.Log("msg", "message"); err != nil { + t.Fatal(err) + } + if want, have := 12, len(output); want != have { + t.Errorf("want len(output) == %v, have %v", want, have) + } + want = []string{ + "a", "first", + "b", "second", + "c", "third", + "msg", "message", + "z", "last", + "aa", "sequel", + } + for i := 0; i < 12; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } +} + // Test that context.Log has a consistent function stack depth when binding // Valuers, regardless of how many times With has been called. func TestContextStackDepth(t *testing.T) { @@ -145,6 +194,43 @@ func TestWithConcurrent(t *testing.T) { } } +func TestLogCopiesValuers(t *testing.T) { + t.Parallel() + var output []interface{} + logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { + output = keyvals + return nil + })) + + valuerCallCount := 0 + counterValuer := log.Valuer(func() interface{} { + valuerCallCount++ + return valuerCallCount + }) + lc := log.WithPrefix(logger, "a", counterValuer) + lc = log.WithSuffix(lc, "z", counterValuer) + + if err := lc.Log(); err != nil { + t.Fatal(err) + } + want := []interface{}{"a", 1, "z", 2} + for i := 0; i < 4; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } + + if err := lc.Log(); err != nil { + t.Fatal(err) + } + want = []interface{}{"a", 3, "z", 4} + for i := 0; i < 4; i++ { + if want, have := want[i], output[i]; want != have { + t.Errorf("want output[%d] == %#v, have %#v", i, want, have) + } + } +} + func BenchmarkDiscard(b *testing.B) { logger := log.NewNopLogger() b.ReportAllocs() @@ -189,3 +275,75 @@ func BenchmarkTenWith(b *testing.B) { lc.Log("k", "v") } } + +func BenchmarkOneWithPrefix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithPrefix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + for i := 1; i < 10; i++ { + lc = log.WithPrefix(lc, "a", "first") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkOneWithSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "z", "last") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "z", "last") + for i := 1; i < 10; i++ { + lc = log.WithSuffix(lc, "z", "last") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkOneWithPrefixSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithSuffix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +} + +func BenchmarkTenWithPrefixSuffix(b *testing.B) { + logger := log.NewNopLogger() + lc := log.WithPrefix(logger, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + for i := 1; i < 10; i++ { + lc = log.WithPrefix(lc, "a", "first") + lc = log.WithSuffix(lc, "z", "last") + } + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + lc.Log("k", "v") + } +}