Merge pull request #992 from vinayvinay/log-with-suffix

Add log.WithSuffix.

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)

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

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

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