Skip to content

Commit

Permalink
log.WithSuffix, appends kvs to those passed to Log
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
Vinay P committed Jul 2, 2020
1 parent b1d0a5d commit e3d5e91
Show file tree
Hide file tree
Showing 2 changed files with 211 additions and 9 deletions.
62 changes: 53 additions & 9 deletions log/log.go
View file
Expand Up @@ -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,
}
}

Expand Down Expand Up @@ -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),
}
}

Expand All @@ -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 {
Expand All @@ -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...)
}
Expand Down
158 changes: 158 additions & 0 deletions log/log_test.go
View file
Expand Up @@ -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) {
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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")
}
}

0 comments on commit e3d5e91

Please sign in to comment.