1package log15
2
3import (
4	"bufio"
5	"bytes"
6	"encoding/json"
7	"errors"
8	"fmt"
9	"net"
10	"regexp"
11	"runtime"
12	"sync"
13	"testing"
14	"time"
15)
16
17func testHandler() (Handler, *Record) {
18	rec := new(Record)
19	return FuncHandler(func(r *Record) error {
20		*rec = *r
21		return nil
22	}), rec
23}
24
25func testLogger() (Logger, Handler, *Record) {
26	l := New()
27	h, r := testHandler()
28	l.SetHandler(LazyHandler(h))
29	return l, h, r
30}
31
32func TestLazy(t *testing.T) {
33	t.Parallel()
34
35	x := 1
36	lazy := func() int {
37		return x
38	}
39
40	l, _, r := testLogger()
41	l.Info("", "x", Lazy{lazy})
42	if r.Ctx[1] != 1 {
43		t.Fatalf("Lazy function not evaluated, got %v, expected %d", r.Ctx[1], 1)
44	}
45
46	x = 2
47	l.Info("", "x", Lazy{lazy})
48	if r.Ctx[1] != 2 {
49		t.Fatalf("Lazy function not evaluated, got %v, expected %d", r.Ctx[1], 1)
50	}
51}
52
53func TestInvalidLazy(t *testing.T) {
54	t.Parallel()
55
56	l, _, r := testLogger()
57	validate := func() {
58		if len(r.Ctx) < 4 {
59			t.Fatalf("Invalid lazy, got %d args, expecting at least 4", len(r.Ctx))
60		}
61
62		if r.Ctx[2] != errorKey {
63			t.Fatalf("Invalid lazy, got key %s expecting %s", r.Ctx[2], errorKey)
64		}
65	}
66
67	l.Info("", "x", Lazy{1})
68	validate()
69
70	l.Info("", "x", Lazy{func(x int) int { return x }})
71	validate()
72
73	l.Info("", "x", Lazy{func() {}})
74	validate()
75}
76
77func TestCtx(t *testing.T) {
78	t.Parallel()
79
80	l, _, r := testLogger()
81	l.Info("", Ctx{"x": 1, "y": "foo", "tester": t})
82	if len(r.Ctx) != 6 {
83		t.Fatalf("Expecting Ctx tansformed into %d ctx args, got %d: %v", 6, len(r.Ctx), r.Ctx)
84	}
85}
86
87func testFormatter(f Format) (Logger, *bytes.Buffer) {
88	l := New()
89	var buf bytes.Buffer
90	l.SetHandler(StreamHandler(&buf, f))
91	return l, &buf
92}
93
94func TestJson(t *testing.T) {
95	t.Parallel()
96
97	l, buf := testFormatter(JsonFormat())
98	l.Error("some message", "x", 1, "y", 3.2)
99
100	var v map[string]interface{}
101	decoder := json.NewDecoder(buf)
102	if err := decoder.Decode(&v); err != nil {
103		t.Fatalf("Error decoding JSON: %v", v)
104	}
105
106	validate := func(key string, expected interface{}) {
107		if v[key] != expected {
108			t.Fatalf("Got %v expected %v for %v", v[key], expected, key)
109		}
110	}
111
112	validate("msg", "some message")
113	validate("x", float64(1)) // all numbers are floats in JSON land
114	validate("y", 3.2)
115	validate("lvl", "eror")
116}
117
118func TestJSONMap(t *testing.T) {
119	m := map[string]interface{}{
120		"name":     "gopher",
121		"age":      float64(5),
122		"language": "go",
123	}
124
125	l, buf := testFormatter(JsonFormat())
126	l.Error("logging structs", "struct", m)
127
128	var v map[string]interface{}
129	decoder := json.NewDecoder(buf)
130	if err := decoder.Decode(&v); err != nil {
131		t.Fatalf("Error decoding JSON: %v", v)
132	}
133
134	checkMap := func(key string, expected interface{}) {
135		if m[key] != expected {
136			t.Fatalf("Got %v expected %v for %v", m[key], expected, key)
137		}
138	}
139
140	mv := v["struct"].(map[string]interface{})
141	checkMap("name", mv["name"])
142	checkMap("age", mv["age"])
143	checkMap("language", mv["language"])
144}
145
146type testtype struct {
147	name string
148}
149
150func (tt testtype) String() string {
151	return tt.name
152}
153
154func TestLogfmt(t *testing.T) {
155	t.Parallel()
156
157	var nilVal *testtype
158
159	l, buf := testFormatter(LogfmtFormat())
160	l.Error("some message", "x", 1, "y", 3.2, "equals", "=", "quote", "\"",
161		"nil", nilVal, "carriage_return", "bang"+string('\r')+"foo", "tab", "bar	baz", "newline", "foo\nbar")
162
163	// skip timestamp in comparison
164	got := buf.Bytes()[27:buf.Len()]
165	expected := []byte(`lvl=eror msg="some message" x=1 y=3.200 equals="=" quote="\"" nil=nil carriage_return="bang\rfoo" tab="bar\tbaz" newline="foo\nbar"` + "\n")
166	if !bytes.Equal(got, expected) {
167		t.Fatalf("Got %s, expected %s", got, expected)
168	}
169}
170
171func TestMultiHandler(t *testing.T) {
172	t.Parallel()
173
174	h1, r1 := testHandler()
175	h2, r2 := testHandler()
176	l := New()
177	l.SetHandler(MultiHandler(h1, h2))
178	l.Debug("clone")
179
180	if r1.Msg != "clone" {
181		t.Fatalf("wrong value for h1.Msg. Got %s expected %s", r1.Msg, "clone")
182	}
183
184	if r2.Msg != "clone" {
185		t.Fatalf("wrong value for h2.Msg. Got %s expected %s", r2.Msg, "clone")
186	}
187
188}
189
190type waitHandler struct {
191	ch chan Record
192}
193
194func (h *waitHandler) Log(r *Record) error {
195	h.ch <- *r
196	return nil
197}
198
199func TestBufferedHandler(t *testing.T) {
200	t.Parallel()
201
202	ch := make(chan Record)
203	l := New()
204	l.SetHandler(BufferedHandler(0, &waitHandler{ch}))
205
206	l.Debug("buffer")
207	if r := <-ch; r.Msg != "buffer" {
208		t.Fatalf("wrong value for r.Msg. Got %s expected %s", r.Msg, "")
209	}
210}
211
212func TestLogContext(t *testing.T) {
213	t.Parallel()
214
215	l, _, r := testLogger()
216	l = l.New("foo", "bar")
217	l.Crit("baz")
218
219	if len(r.Ctx) != 2 {
220		t.Fatalf("Expected logger context in record context. Got length %d, expected %d", len(r.Ctx), 2)
221	}
222
223	if r.Ctx[0] != "foo" {
224		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], "foo")
225	}
226
227	if r.Ctx[1] != "bar" {
228		t.Fatalf("Wrong context value, got %s expected %s", r.Ctx[1], "bar")
229	}
230}
231
232func TestMapCtx(t *testing.T) {
233	t.Parallel()
234
235	l, _, r := testLogger()
236	l.Crit("test", Ctx{"foo": "bar"})
237
238	if len(r.Ctx) != 2 {
239		t.Fatalf("Wrong context length, got %d, expected %d", len(r.Ctx), 2)
240	}
241
242	if r.Ctx[0] != "foo" {
243		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], "foo")
244	}
245
246	if r.Ctx[1] != "bar" {
247		t.Fatalf("Wrong context value, got %s expected %s", r.Ctx[1], "bar")
248	}
249}
250
251func TestLvlFilterHandler(t *testing.T) {
252	t.Parallel()
253
254	l := New()
255	h, r := testHandler()
256	l.SetHandler(LvlFilterHandler(LvlWarn, h))
257	l.Info("info'd")
258
259	if r.Msg != "" {
260		t.Fatalf("Expected zero record, but got record with msg: %v", r.Msg)
261	}
262
263	l.Warn("warned")
264	if r.Msg != "warned" {
265		t.Fatalf("Got record msg %s expected %s", r.Msg, "warned")
266	}
267
268	l.Warn("error'd")
269	if r.Msg != "error'd" {
270		t.Fatalf("Got record msg %s expected %s", r.Msg, "error'd")
271	}
272}
273
274func TestNetHandler(t *testing.T) {
275	t.Parallel()
276
277	l, err := net.Listen("tcp", "localhost:0")
278	if err != nil {
279		t.Fatalf("Failed to listen: %v", l)
280	}
281
282	errs := make(chan error)
283	go func() {
284		c, err := l.Accept()
285		if err != nil {
286			errs <- fmt.Errorf("Failed to accept connection: %v", err)
287			return
288		}
289
290		rd := bufio.NewReader(c)
291		s, err := rd.ReadString('\n')
292		if err != nil {
293			errs <- fmt.Errorf("Failed to read string: %v", err)
294			return
295		}
296
297		got := s[27:]
298		expected := "lvl=info msg=test x=1\n"
299		if got != expected {
300			t.Errorf("Got log line %s, expected %s", got, expected)
301		}
302
303		errs <- nil
304	}()
305
306	lg := New()
307	h, err := NetHandler("tcp", l.Addr().String(), LogfmtFormat())
308	if err != nil {
309		t.Fatal(err)
310	}
311	lg.SetHandler(h)
312	lg.Info("test", "x", 1)
313
314	select {
315	case <-time.After(time.Second):
316		t.Fatalf("Test timed out!")
317	case err := <-errs:
318		if err != nil {
319			t.Fatal(err)
320		}
321	}
322}
323
324func TestMatchFilterHandler(t *testing.T) {
325	t.Parallel()
326
327	l, h, r := testLogger()
328	l.SetHandler(MatchFilterHandler("err", nil, h))
329
330	l.Crit("test", "foo", "bar")
331	if r.Msg != "" {
332		t.Fatalf("expected filter handler to discard msg")
333	}
334
335	l.Crit("test2", "err", "bad fd")
336	if r.Msg != "" {
337		t.Fatalf("expected filter handler to discard msg")
338	}
339
340	l.Crit("test3", "err", nil)
341	if r.Msg != "test3" {
342		t.Fatalf("expected filter handler to allow msg")
343	}
344}
345
346func TestMatchFilterBuiltin(t *testing.T) {
347	t.Parallel()
348
349	l, h, r := testLogger()
350	l.SetHandler(MatchFilterHandler("lvl", LvlError, h))
351	l.Info("does not pass")
352
353	if r.Msg != "" {
354		t.Fatalf("got info level record that should not have matched")
355	}
356
357	l.Error("error!")
358	if r.Msg != "error!" {
359		t.Fatalf("did not get error level record that should have matched")
360	}
361
362	r.Msg = ""
363	l.SetHandler(MatchFilterHandler("msg", "matching message", h))
364	l.Info("doesn't match")
365	if r.Msg != "" {
366		t.Fatalf("got record with wrong message matched")
367	}
368
369	l.Debug("matching message")
370	if r.Msg != "matching message" {
371		t.Fatalf("did not get record which matches")
372	}
373}
374
375type failingWriter struct {
376	fail bool
377}
378
379func (w *failingWriter) Write(buf []byte) (int, error) {
380	if w.fail {
381		return 0, errors.New("fail")
382	}
383	return len(buf), nil
384}
385
386func TestFailoverHandler(t *testing.T) {
387	t.Parallel()
388
389	l := New()
390	h, r := testHandler()
391	w := &failingWriter{false}
392
393	l.SetHandler(FailoverHandler(
394		StreamHandler(w, JsonFormat()),
395		h))
396
397	l.Debug("test ok")
398	if r.Msg != "" {
399		t.Fatalf("expected no failover")
400	}
401
402	w.fail = true
403	l.Debug("test failover", "x", 1)
404	if r.Msg != "test failover" {
405		t.Fatalf("expected failover")
406	}
407
408	if len(r.Ctx) != 4 {
409		t.Fatalf("expected additional failover ctx")
410	}
411
412	got := r.Ctx[2]
413	expected := "failover_err_0"
414	if got != expected {
415		t.Fatalf("expected failover ctx. got: %s, expected %s", got, expected)
416	}
417}
418
419// https://github.com/inconshreveable/log15/issues/16
420func TestIndependentSetHandler(t *testing.T) {
421	t.Parallel()
422
423	parent, _, r := testLogger()
424	child := parent.New()
425	child.SetHandler(DiscardHandler())
426	parent.Info("test")
427	if r.Msg != "test" {
428		t.Fatalf("parent handler affected by child")
429	}
430}
431
432// https://github.com/inconshreveable/log15/issues/16
433func TestInheritHandler(t *testing.T) {
434	t.Parallel()
435
436	parent, _, r := testLogger()
437	child := parent.New()
438	parent.SetHandler(DiscardHandler())
439	child.Info("test")
440	if r.Msg == "test" {
441		t.Fatalf("child handler affected not affected by parent")
442	}
443}
444
445func TestCallerFileHandler(t *testing.T) {
446	t.Parallel()
447
448	l := New()
449	h, r := testHandler()
450	l.SetHandler(CallerFileHandler(h))
451
452	l.Info("baz")
453	_, _, line, _ := runtime.Caller(0)
454
455	if len(r.Ctx) != 2 {
456		t.Fatalf("Expected caller in record context. Got length %d, expected %d", len(r.Ctx), 2)
457	}
458
459	const key = "caller"
460
461	if r.Ctx[0] != key {
462		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
463	}
464
465	s, ok := r.Ctx[1].(string)
466	if !ok {
467		t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
468	}
469
470	exp := fmt.Sprint("log15_test.go:", line-1)
471	if s != exp {
472		t.Fatalf("Wrong context value, got %s expected string matching %s", s, exp)
473	}
474}
475
476func TestCallerFuncHandler(t *testing.T) {
477	t.Parallel()
478
479	l := New()
480	h, r := testHandler()
481	l.SetHandler(CallerFuncHandler(h))
482
483	l.Info("baz")
484
485	if len(r.Ctx) != 2 {
486		t.Fatalf("Expected caller in record context. Got length %d, expected %d", len(r.Ctx), 2)
487	}
488
489	const key = "fn"
490
491	if r.Ctx[0] != key {
492		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
493	}
494
495	const regex = ".*\\.TestCallerFuncHandler"
496
497	s, ok := r.Ctx[1].(string)
498	if !ok {
499		t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
500	}
501
502	match, err := regexp.MatchString(regex, s)
503	if err != nil {
504		t.Fatalf("Error matching %s to regex %s: %v", s, regex, err)
505	}
506
507	if !match {
508		t.Fatalf("Wrong context value, got %s expected string matching %s", s, regex)
509	}
510}
511
512// https://github.com/inconshreveable/log15/issues/27
513func TestCallerStackHandler(t *testing.T) {
514	t.Parallel()
515
516	l := New()
517	h, r := testHandler()
518	l.SetHandler(CallerStackHandler("%#v", h))
519
520	lines := []int{}
521
522	func() {
523		l.Info("baz")
524		_, _, line, _ := runtime.Caller(0)
525		lines = append(lines, line-1)
526	}()
527	_, file, line, _ := runtime.Caller(0)
528	lines = append(lines, line-1)
529
530	if len(r.Ctx) != 2 {
531		t.Fatalf("Expected stack in record context. Got length %d, expected %d", len(r.Ctx), 2)
532	}
533
534	const key = "stack"
535
536	if r.Ctx[0] != key {
537		t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
538	}
539
540	s, ok := r.Ctx[1].(string)
541	if !ok {
542		t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
543	}
544
545	exp := "["
546	for i, line := range lines {
547		if i > 0 {
548			exp += " "
549		}
550		exp += fmt.Sprint(file, ":", line)
551	}
552	exp += "]"
553
554	if s != exp {
555		t.Fatalf("Wrong context value, got %s expected string matching %s", s, exp)
556	}
557}
558
559// tests that when logging concurrently to the same logger
560// from multiple goroutines that the calls are handled independently
561// this test tries to trigger a previous bug where concurrent calls could
562// corrupt each other's context values
563//
564// this test runs N concurrent goroutines each logging a fixed number of
565// records and a handler that buckets them based on the index passed in the context.
566// if the logger is not concurrent-safe then the values in the buckets will not all be the same
567//
568// https://github.com/inconshreveable/log15/pull/30
569func TestConcurrent(t *testing.T) {
570	root := New()
571	// this was the first value that triggered
572	// go to allocate extra capacity in the logger's context slice which
573	// was necessary to trigger the bug
574	const ctxLen = 34
575	l := root.New(make([]interface{}, ctxLen)...)
576	const goroutines = 8
577	var res [goroutines]int
578	l.SetHandler(SyncHandler(FuncHandler(func(r *Record) error {
579		res[r.Ctx[ctxLen+1].(int)]++
580		return nil
581	})))
582	var wg sync.WaitGroup
583	wg.Add(goroutines)
584	for i := 0; i < goroutines; i++ {
585		go func(idx int) {
586			defer wg.Done()
587			for j := 0; j < 10000; j++ {
588				l.Info("test message", "goroutine_idx", idx)
589			}
590		}(i)
591	}
592	wg.Wait()
593	for _, val := range res[:] {
594		if val != 10000 {
595			t.Fatalf("Wrong number of messages for context: %+v", res)
596		}
597	}
598}
599