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