From 0268ca8a0178838b8c174a7ffcd15f0bd5ab8168 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/doc.go | 4 +- log/log.go | 82 +++++++++++++++++++------ log/log_test.go | 158 ++++++++++++++++++++++++++++++++++++++++++++++++ log/value.go | 6 +- 4 files changed, 226 insertions(+), 24 deletions(-) diff --git a/log/doc.go b/log/doc.go index 918c0af46..f744382fe 100644 --- a/log/doc.go +++ b/log/doc.go @@ -39,8 +39,8 @@ // // A contextual logger stores keyvals that it includes in all log events. // Building appropriate contextual loggers reduces repetition and aids -// consistency in the resulting log output. With and WithPrefix add context to -// a logger. We can use With to improve the RunTask example. +// consistency in the resulting log output. With, WithPrefix, and WithSuffix +// add context to a logger. We can use With to improve the RunTask example. // // func RunTask(task Task, logger log.Logger) string { // logger = log.With(logger, "taskID", task.ID) diff --git a/log/log.go b/log/log.go index 66a9e2fde..29b3b82ff 100644 --- a/log/log.go +++ b/log/log.go @@ -16,8 +16,8 @@ type Logger interface { var ErrMissingValue = errors.New("(MISSING)") // With returns a new contextual logger with keyvals prepended to those passed -// to calls to Log. If logger is also a contextual logger created by With or -// WithPrefix, keyvals is appended to the existing context. +// to calls to Log. If logger is also a contextual logger created by With, +// WithPrefix, or WithSuffix, 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. @@ -36,14 +36,16 @@ 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, } } // WithPrefix returns a new contextual logger with keyvals prepended to those // passed to calls to Log. If logger is also a contextual logger created by -// With or WithPrefix, keyvals is prepended to the existing context. +// With, WithPrefix, or WithSuffix, keyvals is prepended 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. @@ -67,16 +69,52 @@ 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, } } -// context is the Logger implementation returned by With and WithPrefix. It -// wraps a Logger and holds keyvals that it includes in all log events. Its -// Log method calls bindValues to generate values for each Valuer in the -// context keyvals. +// WithSuffix returns a new contextual logger with keyvals appended to those +// passed to calls to Log. If logger is also a contextual logger created by +// With, WithPrefix, or WithSuffix, 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), + } +} + +// context is the Logger implementation returned by With, WithPrefix, and +// WithSuffix. It wraps a Logger and holds keyvals that it includes in all +// log events. Its Log method calls bindValues to generate values for each +// Valuer in the context keyvals. // // A context must always have the same number of stack frames between calls to // its Log method and the eventual binding of Valuers to their value. This @@ -89,13 +127,15 @@ func WithPrefix(logger Logger, keyvals ...interface{}) Logger { // // 1. newContext avoids introducing an additional layer when asked to // wrap another context. -// 2. With and WithPrefix avoid introducing an additional layer by -// returning a newly constructed context with a merged keyvals rather -// than simply wrapping the existing context. +// 2. With, WithPrefix, and WithSuffix avoid introducing an additional +// layer by 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") + } +} diff --git a/log/value.go b/log/value.go index 1486f145d..3ce197f78 100644 --- a/log/value.go +++ b/log/value.go @@ -7,9 +7,9 @@ import ( "time" ) -// A Valuer generates a log value. When passed to With or WithPrefix in a -// value element (odd indexes), it represents a dynamic value which is re- -// evaluated with each log event. +// A Valuer generates a log value. When passed to With, WithPrefix, or +// WithSuffix in a value element (odd indexes), it represents a dynamic +// value which is re-evaluated with each log event. type Valuer func() interface{} // bindValues replaces all value elements (odd indexes) containing a Valuer