1package hclog
2
3import (
4	"bytes"
5	"encoding/json"
6	"errors"
7	"fmt"
8	"io"
9	"runtime"
10	"strconv"
11	"strings"
12	"testing"
13	"time"
14
15	"github.com/stretchr/testify/assert"
16	"github.com/stretchr/testify/require"
17)
18
19type bufferingBuffer struct {
20	held    bytes.Buffer
21	flushed bytes.Buffer
22}
23
24func (b *bufferingBuffer) Write(p []byte) (int, error) {
25	return b.held.Write(p)
26}
27
28func (b *bufferingBuffer) String() string {
29	return b.flushed.String()
30}
31
32func (b *bufferingBuffer) Flush() error {
33	_, err := b.flushed.WriteString(b.held.String())
34	return err
35}
36
37func TestLogger(t *testing.T) {
38	t.Run("uses default output if none is given", func(t *testing.T) {
39		var buf bytes.Buffer
40		DefaultOutput = &buf
41
42		logger := New(&LoggerOptions{
43			Name: "test",
44		})
45
46		logger.Info("this is test", "who", "programmer", "why", "testing")
47
48		str := buf.String()
49		dataIdx := strings.IndexByte(str, ' ')
50		rest := str[dataIdx+1:]
51
52		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", rest)
53	})
54
55	t.Run("formats log entries", func(t *testing.T) {
56		var buf bytes.Buffer
57
58		logger := New(&LoggerOptions{
59			Name:   "test",
60			Output: &buf,
61		})
62
63		logger.Info("this is test", "who", "programmer", "why", "testing")
64
65		str := buf.String()
66		dataIdx := strings.IndexByte(str, ' ')
67		rest := str[dataIdx+1:]
68
69		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", rest)
70	})
71
72	t.Run("renders slice values specially", func(t *testing.T) {
73		var buf bytes.Buffer
74
75		logger := New(&LoggerOptions{
76			Name:   "test",
77			Output: &buf,
78		})
79
80		logger.Info("this is test", "who", "programmer", "why", []interface{}{"testing", "dev", 1, uint64(5), []int{3, 4}})
81
82		str := buf.String()
83		dataIdx := strings.IndexByte(str, ' ')
84		rest := str[dataIdx+1:]
85
86		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=[testing, dev, 1, 5, \"[3 4]\"]\n", rest)
87	})
88
89	t.Run("renders values in slices with quotes if needed", func(t *testing.T) {
90		var buf bytes.Buffer
91
92		logger := New(&LoggerOptions{
93			Name:   "test",
94			Output: &buf,
95		})
96
97		logger.Info("this is test", "who", "programmer", "why", []string{"testing & qa", "dev"})
98
99		str := buf.String()
100		dataIdx := strings.IndexByte(str, ' ')
101		rest := str[dataIdx+1:]
102
103		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=[\"testing & qa\", dev]\n", rest)
104	})
105
106	t.Run("outputs stack traces", func(t *testing.T) {
107		var buf bytes.Buffer
108
109		logger := New(&LoggerOptions{
110			Name:   "test",
111			Output: &buf,
112		})
113
114		logger.Info("who", "programmer", "why", "testing", Stacktrace())
115
116		lines := strings.Split(buf.String(), "\n")
117		require.True(t, len(lines) > 1)
118
119		assert.Equal(t, "github.com/hashicorp/go-hclog.Stacktrace", lines[1])
120	})
121
122	t.Run("outputs stack traces with it's given a name", func(t *testing.T) {
123		var buf bytes.Buffer
124
125		logger := New(&LoggerOptions{
126			Name:   "test",
127			Output: &buf,
128		})
129
130		logger.Info("who", "programmer", "why", "testing", "foo", Stacktrace())
131
132		lines := strings.Split(buf.String(), "\n")
133		require.True(t, len(lines) > 1)
134
135		assert.Equal(t, "github.com/hashicorp/go-hclog.Stacktrace", lines[1])
136	})
137
138	t.Run("includes the caller location", func(t *testing.T) {
139		var buf bytes.Buffer
140
141		logger := New(&LoggerOptions{
142			Name:            "test",
143			Output:          &buf,
144			IncludeLocation: true,
145		})
146
147		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
148
149		str := buf.String()
150		dataIdx := strings.IndexByte(str, ' ')
151		rest := str[dataIdx+1:]
152
153		// This test will break if you move this around, it's line dependent, just fyi
154		assert.Equal(t, "[INFO]  go-hclog/logger_test.go:147: test: this is test: who=programmer why=\"testing is fun\"\n", rest)
155	})
156
157	t.Run("prefixes the name", func(t *testing.T) {
158		var buf bytes.Buffer
159
160		logger := New(&LoggerOptions{
161			// No name!
162			Output: &buf,
163		})
164
165		logger.Info("this is test")
166		str := buf.String()
167		dataIdx := strings.IndexByte(str, ' ')
168		rest := str[dataIdx+1:]
169		assert.Equal(t, "[INFO]  this is test\n", rest)
170
171		buf.Reset()
172
173		another := logger.Named("sublogger")
174		another.Info("this is test")
175		str = buf.String()
176		dataIdx = strings.IndexByte(str, ' ')
177		rest = str[dataIdx+1:]
178		assert.Equal(t, "[INFO]  sublogger: this is test\n", rest)
179	})
180
181	t.Run("use a different time format", func(t *testing.T) {
182		var buf bytes.Buffer
183
184		logger := New(&LoggerOptions{
185			Name:       "test",
186			Output:     &buf,
187			TimeFormat: time.Kitchen,
188		})
189
190		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
191
192		str := buf.String()
193		dataIdx := strings.IndexByte(str, ' ')
194
195		assert.Equal(t, str[:dataIdx], time.Now().Format(time.Kitchen))
196	})
197
198	t.Run("use with", func(t *testing.T) {
199		var buf bytes.Buffer
200
201		rootLogger := New(&LoggerOptions{
202			Name:   "with_test",
203			Output: &buf,
204		})
205
206		// Build the root logger in two steps, which triggers a slice capacity increase
207		// and is part of the test for inadvertant slice aliasing.
208		rootLogger = rootLogger.With("a", 1, "b", 2)
209		rootLogger = rootLogger.With("c", 3)
210
211		// Derive two new loggers which should be completely independent
212		derived1 := rootLogger.With("cat", 30)
213		derived2 := rootLogger.With("dog", 40)
214
215		derived1.Info("test1")
216		output := buf.String()
217		dataIdx := strings.IndexByte(output, ' ')
218		assert.Equal(t, "[INFO]  with_test: test1: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
219
220		buf.Reset()
221
222		derived2.Info("test2")
223		output = buf.String()
224		dataIdx = strings.IndexByte(output, ' ')
225		assert.Equal(t, "[INFO]  with_test: test2: a=1 b=2 c=3 dog=40\n", output[dataIdx+1:])
226	})
227
228	t.Run("unpaired with", func(t *testing.T) {
229		var buf bytes.Buffer
230
231		rootLogger := New(&LoggerOptions{
232			Name:   "with_test",
233			Output: &buf,
234		})
235
236		derived1 := rootLogger.With("a")
237		derived1.Info("test1")
238		output := buf.String()
239		dataIdx := strings.IndexByte(output, ' ')
240		assert.Equal(t, "[INFO]  with_test: test1: EXTRA_VALUE_AT_END=a\n", output[dataIdx+1:])
241	})
242
243	t.Run("use with and log", func(t *testing.T) {
244		var buf bytes.Buffer
245
246		rootLogger := New(&LoggerOptions{
247			Name:   "with_test",
248			Output: &buf,
249		})
250
251		// Build the root logger in two steps, which triggers a slice capacity increase
252		// and is part of the test for inadvertant slice aliasing.
253		rootLogger = rootLogger.With("a", 1, "b", 2)
254		// This line is here to test that when calling With with the same key,
255		// only the last value remains (see issue #21)
256		rootLogger = rootLogger.With("c", 4)
257		rootLogger = rootLogger.With("c", 3)
258
259		// Derive another logger which should be completely independent of rootLogger
260		derived := rootLogger.With("cat", 30)
261
262		rootLogger.Info("root_test", "bird", 10)
263		output := buf.String()
264		dataIdx := strings.IndexByte(output, ' ')
265		assert.Equal(t, "[INFO]  with_test: root_test: a=1 b=2 c=3 bird=10\n", output[dataIdx+1:])
266
267		buf.Reset()
268
269		derived.Info("derived_test")
270		output = buf.String()
271		dataIdx = strings.IndexByte(output, ' ')
272		assert.Equal(t, "[INFO]  with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
273	})
274
275	t.Run("use with and log and change levels", func(t *testing.T) {
276		var buf bytes.Buffer
277
278		rootLogger := New(&LoggerOptions{
279			Name:   "with_test",
280			Output: &buf,
281			Level:  Warn,
282		})
283
284		// Build the root logger in two steps, which triggers a slice capacity increase
285		// and is part of the test for inadvertant slice aliasing.
286		rootLogger = rootLogger.With("a", 1, "b", 2)
287		rootLogger = rootLogger.With("c", 3)
288
289		// Derive another logger which should be completely independent of rootLogger
290		derived := rootLogger.With("cat", 30)
291
292		rootLogger.Info("root_test", "bird", 10)
293		output := buf.String()
294		if output != "" {
295			t.Fatalf("unexpected output: %s", output)
296		}
297
298		buf.Reset()
299
300		derived.Info("derived_test")
301		output = buf.String()
302		if output != "" {
303			t.Fatalf("unexpected output: %s", output)
304		}
305
306		derived.SetLevel(Info)
307
308		rootLogger.Info("root_test", "bird", 10)
309		output = buf.String()
310		dataIdx := strings.IndexByte(output, ' ')
311		assert.Equal(t, "[INFO]  with_test: root_test: a=1 b=2 c=3 bird=10\n", output[dataIdx+1:])
312
313		buf.Reset()
314
315		derived.Info("derived_test")
316		output = buf.String()
317		dataIdx = strings.IndexByte(output, ' ')
318		assert.Equal(t, "[INFO]  with_test: derived_test: a=1 b=2 c=3 cat=30\n", output[dataIdx+1:])
319	})
320
321	t.Run("supports Printf style expansions when requested", func(t *testing.T) {
322		var buf bytes.Buffer
323
324		logger := New(&LoggerOptions{
325			Name:   "test",
326			Output: &buf,
327		})
328
329		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
330
331		str := buf.String()
332		dataIdx := strings.IndexByte(str, ' ')
333		rest := str[dataIdx+1:]
334
335		assert.Equal(t, "[INFO]  test: this is test: production=\"12 beans/day\"\n", rest)
336	})
337
338	t.Run("supports resetting the output", func(t *testing.T) {
339		var first, second bytes.Buffer
340
341		logger := New(&LoggerOptions{
342			Output: &first,
343		})
344
345		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
346
347		str := first.String()
348		dataIdx := strings.IndexByte(str, ' ')
349		rest := str[dataIdx+1:]
350
351		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
352
353		logger.(OutputResettable).ResetOutput(&LoggerOptions{
354			Output: &second,
355		})
356
357		logger.Info("this is another test", "production", Fmt("%d beans/day", 13))
358
359		str = first.String()
360		dataIdx = strings.IndexByte(str, ' ')
361		rest = str[dataIdx+1:]
362		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
363
364		str = second.String()
365		dataIdx = strings.IndexByte(str, ' ')
366		rest = str[dataIdx+1:]
367		assert.Equal(t, "[INFO]  this is another test: production=\"13 beans/day\"\n", rest)
368	})
369
370	t.Run("supports resetting the output with flushing", func(t *testing.T) {
371		var first bufferingBuffer
372		var second bytes.Buffer
373
374		logger := New(&LoggerOptions{
375			Output: &first,
376		})
377
378		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
379
380		str := first.String()
381		assert.Empty(t, str)
382
383		logger.(OutputResettable).ResetOutputWithFlush(&LoggerOptions{
384			Output: &second,
385		}, &first)
386
387		logger.Info("this is another test", "production", Fmt("%d beans/day", 13))
388
389		str = first.String()
390		dataIdx := strings.IndexByte(str, ' ')
391		rest := str[dataIdx+1:]
392		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
393
394		str = second.String()
395		dataIdx = strings.IndexByte(str, ' ')
396		rest = str[dataIdx+1:]
397		assert.Equal(t, "[INFO]  this is another test: production=\"13 beans/day\"\n", rest)
398	})
399}
400
401func TestLogger_leveledWriter(t *testing.T) {
402	t.Run("writes errors to stderr", func(t *testing.T) {
403		var stderr bytes.Buffer
404		var stdout bytes.Buffer
405
406		logger := New(&LoggerOptions{
407			Name:   "test",
408			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
409		})
410
411		logger.Error("this is an error", "who", "programmer", "why", "testing")
412
413		errStr := stderr.String()
414		errDataIdx := strings.IndexByte(errStr, ' ')
415		errRest := errStr[errDataIdx+1:]
416
417		assert.Equal(t, "[ERROR] test: this is an error: who=programmer why=testing\n", errRest)
418	})
419
420	t.Run("writes non-errors to stdout", func(t *testing.T) {
421		var stderr bytes.Buffer
422		var stdout bytes.Buffer
423
424		logger := New(&LoggerOptions{
425			Name:   "test",
426			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
427		})
428
429		logger.Info("this is test", "who", "programmer", "why", "testing")
430
431		outStr := stdout.String()
432		outDataIdx := strings.IndexByte(outStr, ' ')
433		outRest := outStr[outDataIdx+1:]
434
435		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", outRest)
436	})
437
438	t.Run("writes errors and non-errors correctly", func(t *testing.T) {
439		var stderr bytes.Buffer
440		var stdout bytes.Buffer
441
442		logger := New(&LoggerOptions{
443			Name:   "test",
444			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
445		})
446
447		logger.Info("this is test", "who", "programmer", "why", "testing")
448		logger.Error("this is an error", "who", "programmer", "why", "testing")
449
450		errStr := stderr.String()
451		errDataIdx := strings.IndexByte(errStr, ' ')
452		errRest := errStr[errDataIdx+1:]
453
454		outStr := stdout.String()
455		outDataIdx := strings.IndexByte(outStr, ' ')
456		outRest := outStr[outDataIdx+1:]
457
458		assert.Equal(t, "[ERROR] test: this is an error: who=programmer why=testing\n", errRest)
459		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", outRest)
460	})
461}
462
463func TestLogger_JSON(t *testing.T) {
464	t.Run("json formatting", func(t *testing.T) {
465		var buf bytes.Buffer
466		logger := New(&LoggerOptions{
467			Name:       "test",
468			Output:     &buf,
469			JSONFormat: true,
470		})
471
472		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
473
474		b := buf.Bytes()
475
476		var raw map[string]interface{}
477		if err := json.Unmarshal(b, &raw); err != nil {
478			t.Fatal(err)
479		}
480
481		assert.Equal(t, "this is test", raw["@message"])
482		assert.Equal(t, "programmer", raw["who"])
483		assert.Equal(t, "testing is fun", raw["why"])
484	})
485
486	t.Run("json formatting with", func(t *testing.T) {
487		var buf bytes.Buffer
488		logger := New(&LoggerOptions{
489			Name:       "test",
490			Output:     &buf,
491			JSONFormat: true,
492		})
493		logger = logger.With("cat", "in the hat", "dog", 42)
494
495		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
496
497		b := buf.Bytes()
498
499		var raw map[string]interface{}
500		if err := json.Unmarshal(b, &raw); err != nil {
501			t.Fatal(err)
502		}
503
504		assert.Equal(t, "this is test", raw["@message"])
505		assert.Equal(t, "programmer", raw["who"])
506		assert.Equal(t, "testing is fun", raw["why"])
507		assert.Equal(t, "in the hat", raw["cat"])
508		assert.Equal(t, float64(42), raw["dog"])
509	})
510
511	t.Run("json formatting error type", func(t *testing.T) {
512		var buf bytes.Buffer
513
514		logger := New(&LoggerOptions{
515			Name:       "test",
516			Output:     &buf,
517			JSONFormat: true,
518		})
519
520		errMsg := errors.New("this is an error")
521		logger.Info("this is test", "who", "programmer", "err", errMsg)
522
523		b := buf.Bytes()
524
525		var raw map[string]interface{}
526		if err := json.Unmarshal(b, &raw); err != nil {
527			t.Fatal(err)
528		}
529
530		assert.Equal(t, "this is test", raw["@message"])
531		assert.Equal(t, "programmer", raw["who"])
532		assert.Equal(t, errMsg.Error(), raw["err"])
533	})
534
535	t.Run("json formatting custom error type json marshaler", func(t *testing.T) {
536		var buf bytes.Buffer
537
538		logger := New(&LoggerOptions{
539			Name:       "test",
540			Output:     &buf,
541			JSONFormat: true,
542		})
543
544		errMsg := &customErrJSON{"this is an error"}
545		rawMsg, err := errMsg.MarshalJSON()
546		if err != nil {
547			t.Fatal(err)
548		}
549		expectedMsg, err := strconv.Unquote(string(rawMsg))
550		if err != nil {
551			t.Fatal(err)
552		}
553
554		logger.Info("this is test", "who", "programmer", "err", errMsg)
555
556		b := buf.Bytes()
557
558		var raw map[string]interface{}
559		if err := json.Unmarshal(b, &raw); err != nil {
560			t.Fatal(err)
561		}
562
563		assert.Equal(t, "this is test", raw["@message"])
564		assert.Equal(t, "programmer", raw["who"])
565		assert.Equal(t, expectedMsg, raw["err"])
566	})
567
568	t.Run("json formatting custom error type text marshaler", func(t *testing.T) {
569		var buf bytes.Buffer
570
571		logger := New(&LoggerOptions{
572			Name:       "test",
573			Output:     &buf,
574			JSONFormat: true,
575		})
576
577		errMsg := &customErrText{"this is an error"}
578		rawMsg, err := errMsg.MarshalText()
579		if err != nil {
580			t.Fatal(err)
581		}
582		expectedMsg := string(rawMsg)
583
584		logger.Info("this is test", "who", "programmer", "err", errMsg)
585
586		b := buf.Bytes()
587
588		var raw map[string]interface{}
589		if err := json.Unmarshal(b, &raw); err != nil {
590			t.Fatal(err)
591		}
592
593		assert.Equal(t, "this is test", raw["@message"])
594		assert.Equal(t, "programmer", raw["who"])
595		assert.Equal(t, expectedMsg, raw["err"])
596	})
597
598	t.Run("supports Printf style expansions when requested", func(t *testing.T) {
599		var buf bytes.Buffer
600
601		logger := New(&LoggerOptions{
602			Name:       "test",
603			Output:     &buf,
604			JSONFormat: true,
605		})
606
607		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
608
609		b := buf.Bytes()
610
611		var raw map[string]interface{}
612		if err := json.Unmarshal(b, &raw); err != nil {
613			t.Fatal(err)
614		}
615
616		assert.Equal(t, "this is test", raw["@message"])
617		assert.Equal(t, "12 beans/day", raw["production"])
618	})
619
620	t.Run("includes the caller location", func(t *testing.T) {
621		var buf bytes.Buffer
622
623		logger := New(&LoggerOptions{
624			Name:            "test",
625			Output:          &buf,
626			JSONFormat:      true,
627			IncludeLocation: true,
628		})
629
630		logger.Info("this is test")
631		_, file, line, ok := runtime.Caller(0)
632		require.True(t, ok)
633
634		b := buf.Bytes()
635
636		var raw map[string]interface{}
637		if err := json.Unmarshal(b, &raw); err != nil {
638			t.Fatal(err)
639		}
640
641		assert.Equal(t, "this is test", raw["@message"])
642		assert.Equal(t, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"])
643
644	})
645
646	t.Run("handles non-serializable entries", func(t *testing.T) {
647		var buf bytes.Buffer
648
649		logger := New(&LoggerOptions{
650			Name:       "test",
651			Output:     &buf,
652			JSONFormat: true,
653		})
654
655		myfunc := func() int { return 42 }
656		logger.Info("this is test", "production", myfunc)
657
658		b := buf.Bytes()
659
660		var raw map[string]interface{}
661		if err := json.Unmarshal(b, &raw); err != nil {
662			t.Fatal(err)
663		}
664
665		assert.Equal(t, "this is test", raw["@message"])
666		assert.Equal(t, errJsonUnsupportedTypeMsg, raw["@warn"])
667	})
668}
669
670type customErrJSON struct {
671	Message string
672}
673
674// error impl.
675func (c *customErrJSON) Error() string {
676	return c.Message
677}
678
679// json.Marshaler impl.
680func (c customErrJSON) MarshalJSON() ([]byte, error) {
681	return []byte(strconv.Quote(fmt.Sprintf("json-marshaler: %s", c.Message))), nil
682}
683
684type customErrText struct {
685	Message string
686}
687
688// error impl.
689func (c *customErrText) Error() string {
690	return c.Message
691}
692
693// text.Marshaler impl.
694func (c customErrText) MarshalText() ([]byte, error) {
695	return []byte(fmt.Sprintf("text-marshaler: %s", c.Message)), nil
696}
697
698func BenchmarkLogger(b *testing.B) {
699	b.Run("info with 10 pairs", func(b *testing.B) {
700		var buf bytes.Buffer
701
702		logger := New(&LoggerOptions{
703			Name:            "test",
704			Output:          &buf,
705			IncludeLocation: true,
706		})
707
708		for i := 0; i < b.N; i++ {
709			logger.Info("this is some message",
710				"name", "foo",
711				"what", "benchmarking yourself",
712				"why", "to see what's slow",
713				"k4", "value",
714				"k5", "value",
715				"k6", "value",
716				"k7", "value",
717				"k8", "value",
718				"k9", "value",
719				"k10", "value",
720			)
721		}
722	})
723}
724