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