log_test.go

Documentation: github.com/go-kit/log

     1  package log_test
     2  
     3  import (
     4  	"bytes"
     5  	"runtime"
     6  	"sync"
     7  	"testing"
     8  
     9  	"github.com/go-kit/log"
    10  )
    11  
    12  func TestContext(t *testing.T) {
    13  	t.Parallel()
    14  	buf := &bytes.Buffer{}
    15  	logger := log.NewLogfmtLogger(buf)
    16  
    17  	kvs := []interface{}{"a", 123}
    18  	lc := log.With(logger, kvs...)
    19  	kvs[1] = 0 // With should copy its key values
    20  
    21  	lc = log.With(lc, "b", "c") // With should stack
    22  	if err := lc.Log("msg", "message"); err != nil {
    23  		t.Fatal(err)
    24  	}
    25  	if want, have := "a=123 b=c msg=message\n", buf.String(); want != have {
    26  		t.Errorf("\nwant: %shave: %s", want, have)
    27  	}
    28  
    29  	buf.Reset()
    30  	lc = log.WithPrefix(lc, "p", "first")
    31  	if err := lc.Log("msg", "message"); err != nil {
    32  		t.Fatal(err)
    33  	}
    34  	if want, have := "p=first a=123 b=c msg=message\n", buf.String(); want != have {
    35  		t.Errorf("\nwant: %shave: %s", want, have)
    36  	}
    37  }
    38  
    39  func TestContextMissingValue(t *testing.T) {
    40  	t.Parallel()
    41  	var output []interface{}
    42  	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
    43  		output = keyvals
    44  		return nil
    45  	}))
    46  
    47  	log.WithPrefix(log.With(logger, "k1"), "k0").Log("k2")
    48  	if want, have := 6, len(output); want != have {
    49  		t.Errorf("want len(output) == %v, have %v", want, have)
    50  	}
    51  	for i := 1; i < 6; i += 2 {
    52  		if want, have := log.ErrMissingValue, output[i]; want != have {
    53  			t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
    54  		}
    55  	}
    56  }
    57  
    58  func TestWithPrefixAndSuffix(t *testing.T) {
    59  	t.Parallel()
    60  	var output []interface{}
    61  	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
    62  		output = keyvals
    63  		return nil
    64  	}))
    65  
    66  	lc := log.WithPrefix(logger, "a", "first")
    67  	lc = log.WithSuffix(lc, "z", "last")
    68  	if err := lc.Log("msg", "message"); err != nil {
    69  		t.Fatal(err)
    70  	}
    71  	if want, have := 6, len(output); want != have {
    72  		t.Errorf("want len(output) == %v, have %v", want, have)
    73  	}
    74  	want := []string{"a", "first", "msg", "message", "z", "last"}
    75  	for i := 0; i < 6; i++ {
    76  		if want, have := want[i], output[i]; want != have {
    77  			t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
    78  		}
    79  	}
    80  
    81  	lc = log.With(logger, "b", "second")
    82  	lc = log.WithPrefix(lc, "a", "first")
    83  	lc = log.With(lc, "c", "third")
    84  	lc = log.WithSuffix(lc, "z", "last")
    85  	lc = log.WithSuffix(lc, "aa", "sequel")
    86  	if err := lc.Log("msg", "message"); err != nil {
    87  		t.Fatal(err)
    88  	}
    89  	if want, have := 12, len(output); want != have {
    90  		t.Errorf("want len(output) == %v, have %v", want, have)
    91  	}
    92  	want = []string{
    93  		"a", "first",
    94  		"b", "second",
    95  		"c", "third",
    96  		"msg", "message",
    97  		"z", "last",
    98  		"aa", "sequel",
    99  	}
   100  	for i := 0; i < 12; i++ {
   101  		if want, have := want[i], output[i]; want != have {
   102  			t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
   103  		}
   104  	}
   105  }
   106  
   107  // Test that context.Log has a consistent function stack depth when binding
   108  // Valuers, regardless of how many times With has been called.
   109  func TestContextStackDepth(t *testing.T) {
   110  	t.Parallel()
   111  	fn := callingFunctions()[0]
   112  
   113  	var output []interface{}
   114  
   115  	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
   116  		output = keyvals
   117  		return nil
   118  	}))
   119  
   120  	stackValuer := log.Valuer(func() interface{} {
   121  		for i, f := range callingFunctions() {
   122  			if f == fn {
   123  				return i
   124  			}
   125  		}
   126  		t.Fatal("Test function not found in stack trace.")
   127  		return nil
   128  	})
   129  
   130  	logger = log.With(logger, "stack", stackValuer)
   131  
   132  	// Call through interface to get baseline.
   133  	logger.Log("k", "v")
   134  	want := output[1].(int)
   135  
   136  	for len(output) < 10 {
   137  		logger.Log("k", "v")
   138  		if have := output[1]; have != want {
   139  			t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
   140  		}
   141  
   142  		wrapped := log.With(logger)
   143  		wrapped.Log("k", "v")
   144  		if have := output[1]; have != want {
   145  			t.Errorf("%d Withs: have %v, want %v", len(output)/2-1, have, want)
   146  		}
   147  
   148  		logger = log.With(logger, "k", "v")
   149  	}
   150  }
   151  
   152  // callingFunctions returns the names of the functions on the call stack for the
   153  // current goroutine with element 0 identifying the calling function.
   154  func callingFunctions() []string {
   155  	pcs := make([]uintptr, 10)
   156  	n := runtime.Callers(2, pcs)
   157  	if n == 0 {
   158  		return nil
   159  	}
   160  
   161  	frames := runtime.CallersFrames(pcs[:n])
   162  	funcs := make([]string, 0, n)
   163  
   164  	for {
   165  		frame, more := frames.Next()
   166  		funcs = append(funcs, frame.Function)
   167  		if !more {
   168  			break
   169  		}
   170  	}
   171  
   172  	return funcs
   173  }
   174  
   175  // Test that With returns a Logger safe for concurrent use. This test
   176  // validates that the stored logging context does not get corrupted when
   177  // multiple clients concurrently log additional keyvals.
   178  //
   179  // This test must be run with go test -cpu 2 (or more) to achieve its goal.
   180  func TestWithConcurrent(t *testing.T) {
   181  	// Create some buckets to count how many events each goroutine logs.
   182  	const goroutines = 8
   183  	counts := [goroutines]int{}
   184  
   185  	// This logger extracts a goroutine id from the last value field and
   186  	// increments the referenced bucket.
   187  	logger := log.LoggerFunc(func(kv ...interface{}) error {
   188  		goroutine := kv[len(kv)-1].(int)
   189  		counts[goroutine]++
   190  		return nil
   191  	})
   192  
   193  	// With must be careful about handling slices that can grow without
   194  	// copying the underlying array, so give it a challenge.
   195  	l := log.With(logger, make([]interface{}, 0, 2)...)
   196  
   197  	// Start logging concurrently. Each goroutine logs its id so the logger
   198  	// can bucket the event counts.
   199  	var wg sync.WaitGroup
   200  	wg.Add(goroutines)
   201  	const n = 10000
   202  	for i := 0; i < goroutines; i++ {
   203  		go func(idx int) {
   204  			defer wg.Done()
   205  			for j := 0; j < n; j++ {
   206  				l.Log("goroutineIdx", idx)
   207  			}
   208  		}(i)
   209  	}
   210  	wg.Wait()
   211  
   212  	for bucket, have := range counts {
   213  		if want := n; want != have {
   214  			t.Errorf("bucket %d: want %d, have %d", bucket, want, have) // note Errorf
   215  		}
   216  	}
   217  }
   218  
   219  func TestLogCopiesValuers(t *testing.T) {
   220  	t.Parallel()
   221  	var output []interface{}
   222  	logger := log.Logger(log.LoggerFunc(func(keyvals ...interface{}) error {
   223  		output = keyvals
   224  		return nil
   225  	}))
   226  
   227  	valuerCallCount := 0
   228  	counterValuer := log.Valuer(func() interface{} {
   229  		valuerCallCount++
   230  		return valuerCallCount
   231  	})
   232  	lc := log.WithPrefix(logger, "a", counterValuer)
   233  	lc = log.WithSuffix(lc, "z", counterValuer)
   234  
   235  	if err := lc.Log(); err != nil {
   236  		t.Fatal(err)
   237  	}
   238  	want := []interface{}{"a", 1, "z", 2}
   239  	for i := 0; i < 4; i++ {
   240  		if want, have := want[i], output[i]; want != have {
   241  			t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
   242  		}
   243  	}
   244  
   245  	if err := lc.Log(); err != nil {
   246  		t.Fatal(err)
   247  	}
   248  	want = []interface{}{"a", 3, "z", 4}
   249  	for i := 0; i < 4; i++ {
   250  		if want, have := want[i], output[i]; want != have {
   251  			t.Errorf("want output[%d] == %#v, have %#v", i, want, have)
   252  		}
   253  	}
   254  }
   255  
   256  func BenchmarkDiscard(b *testing.B) {
   257  	logger := log.NewNopLogger()
   258  	b.ReportAllocs()
   259  	b.ResetTimer()
   260  	for i := 0; i < b.N; i++ {
   261  		logger.Log("k", "v")
   262  	}
   263  }
   264  
   265  func BenchmarkOneWith(b *testing.B) {
   266  	logger := log.NewNopLogger()
   267  	lc := log.With(logger, "k", "v")
   268  	b.ReportAllocs()
   269  	b.ResetTimer()
   270  	for i := 0; i < b.N; i++ {
   271  		lc.Log("k", "v")
   272  	}
   273  }
   274  
   275  func BenchmarkTwoWith(b *testing.B) {
   276  	logger := log.NewNopLogger()
   277  	lc := log.With(logger, "k", "v")
   278  	for i := 1; i < 2; i++ {
   279  		lc = log.With(lc, "k", "v")
   280  	}
   281  	b.ReportAllocs()
   282  	b.ResetTimer()
   283  	for i := 0; i < b.N; i++ {
   284  		lc.Log("k", "v")
   285  	}
   286  }
   287  
   288  func BenchmarkTenWith(b *testing.B) {
   289  	logger := log.NewNopLogger()
   290  	lc := log.With(logger, "k", "v")
   291  	for i := 1; i < 10; i++ {
   292  		lc = log.With(lc, "k", "v")
   293  	}
   294  	b.ReportAllocs()
   295  	b.ResetTimer()
   296  	for i := 0; i < b.N; i++ {
   297  		lc.Log("k", "v")
   298  	}
   299  }
   300  
   301  func BenchmarkOneWithPrefix(b *testing.B) {
   302  	logger := log.NewNopLogger()
   303  	lc := log.WithPrefix(logger, "a", "first")
   304  	b.ReportAllocs()
   305  	b.ResetTimer()
   306  	for i := 0; i < b.N; i++ {
   307  		lc.Log("k", "v")
   308  	}
   309  }
   310  
   311  func BenchmarkTenWithPrefix(b *testing.B) {
   312  	logger := log.NewNopLogger()
   313  	lc := log.WithPrefix(logger, "a", "first")
   314  	for i := 1; i < 10; i++ {
   315  		lc = log.WithPrefix(lc, "a", "first")
   316  	}
   317  	b.ReportAllocs()
   318  	b.ResetTimer()
   319  	for i := 0; i < b.N; i++ {
   320  		lc.Log("k", "v")
   321  	}
   322  }
   323  
   324  func BenchmarkOneWithSuffix(b *testing.B) {
   325  	logger := log.NewNopLogger()
   326  	lc := log.WithSuffix(logger, "z", "last")
   327  	b.ReportAllocs()
   328  	b.ResetTimer()
   329  	for i := 0; i < b.N; i++ {
   330  		lc.Log("k", "v")
   331  	}
   332  }
   333  
   334  func BenchmarkTenWithSuffix(b *testing.B) {
   335  	logger := log.NewNopLogger()
   336  	lc := log.WithSuffix(logger, "z", "last")
   337  	for i := 1; i < 10; i++ {
   338  		lc = log.WithSuffix(lc, "z", "last")
   339  	}
   340  	b.ReportAllocs()
   341  	b.ResetTimer()
   342  	for i := 0; i < b.N; i++ {
   343  		lc.Log("k", "v")
   344  	}
   345  }
   346  
   347  func BenchmarkOneWithPrefixSuffix(b *testing.B) {
   348  	logger := log.NewNopLogger()
   349  	lc := log.WithSuffix(logger, "a", "first")
   350  	lc = log.WithSuffix(lc, "z", "last")
   351  	b.ReportAllocs()
   352  	b.ResetTimer()
   353  	for i := 0; i < b.N; i++ {
   354  		lc.Log("k", "v")
   355  	}
   356  }
   357  
   358  func BenchmarkTenWithPrefixSuffix(b *testing.B) {
   359  	logger := log.NewNopLogger()
   360  	lc := log.WithPrefix(logger, "a", "first")
   361  	lc = log.WithSuffix(lc, "z", "last")
   362  	for i := 1; i < 10; i++ {
   363  		lc = log.WithPrefix(lc, "a", "first")
   364  		lc = log.WithSuffix(lc, "z", "last")
   365  	}
   366  	b.ReportAllocs()
   367  	b.ResetTimer()
   368  	for i := 0; i < b.N; i++ {
   369  		lc.Log("k", "v")
   370  	}
   371  }
   372
View as plain text