log.WithSuffix, appends kvs to those passed to Log

enhancement suggested in:
#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

@@ -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