1package log_test
2
3import (
4	"bytes"
5	"runtime"
6	"sync"
7	"testing"
8
9	"github.com/go-kit/log"
10)
11
12func 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
39func 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
58func 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.
109func 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.
154func 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.
180func 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
219func 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
256func 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
265func 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
275func 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
288func 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
301func 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
311func 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
324func 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
334func 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
347func 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
358func 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