Codebase list golang-github-go-kit-kit / 0c243515-0bf2-4b25-8735-9c1038fa7c1b/v0.2.0 log / log_test.go
0c243515-0bf2-4b25-8735-9c1038fa7c1b/v0.2.0

Tree @0c243515-0bf2-4b25-8735-9c1038fa7c1b/v0.2.0 (Download .tar.gz)

log_test.go @0c243515-0bf2-4b25-8735-9c1038fa7c1b/v0.2.0

f307245
 
 
 
d4d79f9
b4980e1
f307245
 
75666f7
bffb8bf
f307245
 
8a32db2
37e3bc0
f307245
8a32db2
 
640c235
8a32db2
 
 
d3c703c
 
f307245
 
8a32db2
 
 
 
 
 
 
 
 
 
 
 
 
 
37e3bc0
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
d4d79f9
 
 
 
 
22fe74f
d4d79f9
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
b4980e1
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
651b069
b4980e1
 
 
 
 
f80830a
b4980e1
 
 
f80830a
b4980e1
 
 
 
 
 
f80830a
 
 
b4980e1
 
 
73532c1
 
a7d50df
73532c1
 
 
 
 
 
 
 
a7d50df
651b069
73532c1
 
 
d3c703c
73532c1
 
 
 
a7d50df
651b069
d3c703c
 
73532c1
 
 
 
d3c703c
73532c1
 
 
 
a7d50df
651b069
d3c703c
 
73532c1
 
 
 
d3c703c
73532c1
 
package log_test

import (
	"bytes"
	"fmt"
	"sync"
	"testing"

	"github.com/go-kit/kit/log"
	"github.com/go-stack/stack"
)

func TestContext(t *testing.T) {
	t.Parallel()
	buf := &bytes.Buffer{}
	logger := log.NewLogfmtLogger(buf)

	kvs := []interface{}{"a", 123}
	lc := log.NewContext(logger).With(kvs...)
	kvs[1] = 0 // With should copy its key values

	lc = lc.With("b", "c") // With should stack
	if err := lc.Log("msg", "message"); err != nil {
		t.Fatal(err)
	}
	if want, have := "a=123 b=c msg=message\n", buf.String(); want != have {
		t.Errorf("\nwant: %shave: %s", want, have)
	}

	buf.Reset()
	lc = lc.WithPrefix("p", "first")
	if err := lc.Log("msg", "message"); err != nil {
		t.Fatal(err)
	}
	if want, have := "p=first a=123 b=c msg=message\n", buf.String(); want != have {
		t.Errorf("\nwant: %shave: %s", want, have)
	}
}

func TestContextMissingValue(t *testing.T) {
	t.Parallel()
	var output []interface{}
	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
		output = keyvals
		return nil
	}))

	lc := log.NewContext(logger)

	lc.Log("k")
	if want, have := 2, len(output); want != have {
		t.Errorf("want len(output) == %v, have %v", want, have)
	}
	if want, have := log.ErrMissingValue, output[1]; want != have {
		t.Errorf("want %#v, have %#v", want, have)
	}

	lc.With("k1").WithPrefix("k0").Log("k2")
	if want, have := 6, len(output); want != have {
		t.Errorf("want len(output) == %v, have %v", want, have)
	}
	for i := 1; i < 6; i += 2 {
		if want, have := log.ErrMissingValue, 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
// log.Valuers, regardless of how many times Context.With has been called or
// whether Context.Log is called via an interface typed variable or a concrete
// typed variable.
func TestContextStackDepth(t *testing.T) {
	t.Parallel()
	fn := fmt.Sprintf("%n", stack.Caller(0))

	var output []interface{}

	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
		output = keyvals
		return nil
	}))

	stackValuer := log.Valuer(func() interface{} {
		for i, c := range stack.Trace() {
			if fmt.Sprintf("%n", c) == fn {
				return i
			}
		}
		t.Fatal("Test function not found in stack trace.")
		return nil
	})

	concrete := log.NewContext(logger).With("stack", stackValuer)
	var iface log.Logger = concrete

	// Call through interface to get baseline.
	iface.Log("k", "v")
	want := output[1].(int)

	for len(output) < 10 {
		concrete.Log("k", "v")
		if have := output[1]; have != want {
			t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
		}

		iface.Log("k", "v")
		if have := output[1]; have != want {
			t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
		}

		wrapped := log.NewContext(concrete)
		wrapped.Log("k", "v")
		if have := output[1]; have != want {
			t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
		}

		concrete = concrete.With("k", "v")
		iface = concrete
	}
}

// Test that With returns a Logger safe for concurrent use. This test
// validates that the stored logging context does not get corrupted when
// multiple clients concurrently log additional keyvals.
//
// This test must be run with go test -cpu 2 (or more) to achieve its goal.
func TestWithConcurrent(t *testing.T) {
	// Create some buckets to count how many events each goroutine logs.
	const goroutines = 8
	counts := [goroutines]int{}

	// This logger extracts a goroutine id from the last value field and
	// increments the referenced bucket.
	logger := log.LoggerFunc(func(kv ...interface{}) error {
		goroutine := kv[len(kv)-1].(int)
		counts[goroutine]++
		return nil
	})

	// With must be careful about handling slices that can grow without
	// copying the underlying array, so give it a challenge.
	l := log.NewContext(logger).With(make([]interface{}, 0, 2)...)

	// Start logging concurrently. Each goroutine logs its id so the logger
	// can bucket the event counts.
	var wg sync.WaitGroup
	wg.Add(goroutines)
	const n = 10000
	for i := 0; i < goroutines; i++ {
		go func(idx int) {
			defer wg.Done()
			for j := 0; j < n; j++ {
				l.Log("goroutineIdx", idx)
			}
		}(i)
	}
	wg.Wait()

	for bucket, have := range counts {
		if want := n; want != have {
			t.Errorf("bucket %d: want %d, have %d", bucket, want, have) // note Errorf
		}
	}
}

func BenchmarkDiscard(b *testing.B) {
	logger := log.NewNopLogger()
	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		logger.Log("k", "v")
	}
}

func BenchmarkOneWith(b *testing.B) {
	logger := log.NewNopLogger()
	lc := log.NewContext(logger).With("k", "v")
	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		lc.Log("k", "v")
	}
}

func BenchmarkTwoWith(b *testing.B) {
	logger := log.NewNopLogger()
	lc := log.NewContext(logger).With("k", "v")
	for i := 1; i < 2; i++ {
		lc = lc.With("k", "v")
	}
	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		lc.Log("k", "v")
	}
}

func BenchmarkTenWith(b *testing.B) {
	logger := log.NewNopLogger()
	lc := log.NewContext(logger).With("k", "v")
	for i := 1; i < 10; i++ {
		lc = lc.With("k", "v")
	}
	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		lc.Log("k", "v")
	}
}