// 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) {
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 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 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 benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
lc := log.NewContext(logger).With("common_key", "common_value")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
f(lc)
}
}
func TestNopLogger(t *testing.T) {
logger := log.NewNopLogger()
if err := logger.Log("abc", 123); err != nil {
t.Error(err)
}
if err := log.NewContext(logger).With("def", "ghi").Log(); err != nil {
t.Error(err)
}
}
func BenchmarkValueBindingTimestamp(b *testing.B) {
logger := log.NewNopLogger()
lc := log.NewContext(logger).With("ts", log.DefaultTimestamp)
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
lc.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 ExampleContext() {
logger := log.NewLogfmtLogger(os.Stdout)
logger.Log("foo", 123)
ctx := log.NewContext(logger).With("level", "info")
ctx.Log()
ctx = ctx.With("msg", "hello")
ctx.Log()
ctx.With("a", 1).Log("b", 2)
// Output:
// foo=123
// level=info
// level=info msg=hello
// level=info msg=hello a=1 b=2
}
// New creates a new leveled logger, wrapping the passed logger.
func New(logger log.Logger, options ...Option) Levels {
l := Levels{
ctx: log.NewContext(logger),
levelKey: "level",
debugValue: "debug",
infoValue: "info",
warnValue: "warn",
errorValue: "error",
critValue: "crit",
}
for _, option := range options {
option(&l)
}
return l
}
func TestValueBinding(t *testing.T) {
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:28", 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:41", 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) {
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 (
"testing"
"github.com/gunjan5/Skywalker/Godeps/_workspace/src/github.com/go-kit/kit/log"
)
func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
lc := log.NewContext(logger).With("common_key", "common_value")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
f(lc)
}
}
var (
baseMessage = func(logger log.Logger) { logger.Log("foo_key", "foo_value") }
withMessage = func(logger log.Logger) { log.NewContext(logger).With("a", "b").Log("c", "d") }
)