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) } } }
func TestKafkaErrors(t *testing.T) { p := newStubProducer(true) errs := make(chan []interface{}, len(spans)) lg := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { for i := 0; i < len(keyvals); i += 2 { if keyvals[i] == "result" && keyvals[i+1] == "failed to produce msg" { errs <- keyvals } } return nil })) c, err := zipkin.NewKafkaCollector( []string{"192.0.2.10:9092"}, zipkin.KafkaProducer(p), zipkin.KafkaLogger(lg), ) if err != nil { t.Fatal(err) } for _, want := range spans { _ = collectSpan(t, c, p, want) } for i := 0; i < len(spans); i++ { select { case <-errs: case <-time.After(100 * time.Millisecond): t.Fatalf("errors not logged. got %d, wanted %d", i, len(spans)) } } }
// 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 } }
func TestValueBinding(t *testing.T) { t.Parallel() var output []interface{} logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { output = keyvals return nil })) start := time.Date(2015, time.April, 25, 0, 0, 0, 0, time.UTC) now := start mocktime := func() time.Time { now = now.Add(time.Second) return now } lc := log.NewContext(logger).With("ts", log.Timestamp(mocktime), "caller", log.DefaultCaller) lc.Log("foo", "bar") timestamp, ok := output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) } if want, have := start.Add(time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } if want, have := "value_test.go:29", fmt.Sprint(output[3]); want != have { t.Errorf("output[3]: want %s, have %s", want, have) } // A second attempt to confirm the bindings are truly dynamic. lc.Log("foo", "bar") timestamp, ok = output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) } if want, have := start.Add(2*time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } if want, have := "value_test.go:42", fmt.Sprint(output[3]); want != have { t.Errorf("output[3]: want %s, have %s", want, have) } }
// 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 TestValueBinding_loggingZeroKeyvals(t *testing.T) { t.Parallel() var output []interface{} logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error { output = keyvals return nil })) start := time.Date(2015, time.April, 25, 0, 0, 0, 0, time.UTC) now := start mocktime := func() time.Time { now = now.Add(time.Second) return now } logger = log.NewContext(logger).With("ts", log.Timestamp(mocktime)) logger.Log() timestamp, ok := output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) } if want, have := start.Add(time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } // A second attempt to confirm the bindings are truly dynamic. logger.Log() timestamp, ok = output[1].(time.Time) if !ok { t.Fatalf("want time.Time, have %T", output[1]) } if want, have := start.Add(2*time.Second), timestamp; want != have { t.Errorf("output[1]: want %v, have %v", want, have) } }
package log_test import ( "bytes" "sync" "testing" "github.com/go-kit/kit/log" ) var discard = log.Logger(log.LoggerFunc(func(...interface{}) error { return nil })) 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")