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:129: 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}
401
402func TestLogger_leveledWriter(t *testing.T) {
403	t.Run("writes errors to stderr", func(t *testing.T) {
404		var stderr bytes.Buffer
405		var stdout bytes.Buffer
406
407		logger := New(&LoggerOptions{
408			Name:   "test",
409			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
410		})
411
412		logger.Error("this is an error", "who", "programmer", "why", "testing")
413
414		errStr := stderr.String()
415		errDataIdx := strings.IndexByte(errStr, ' ')
416		errRest := errStr[errDataIdx+1:]
417
418		assert.Equal(t, "[ERROR] test: this is an error: who=programmer why=testing\n", errRest)
419	})
420
421	t.Run("writes non-errors to stdout", func(t *testing.T) {
422		var stderr bytes.Buffer
423		var stdout bytes.Buffer
424
425		logger := New(&LoggerOptions{
426			Name:   "test",
427			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
428		})
429
430		logger.Info("this is test", "who", "programmer", "why", "testing")
431
432		outStr := stdout.String()
433		outDataIdx := strings.IndexByte(outStr, ' ')
434		outRest := outStr[outDataIdx+1:]
435
436		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", outRest)
437	})
438
439	t.Run("writes errors and non-errors correctly", func(t *testing.T) {
440		var stderr bytes.Buffer
441		var stdout bytes.Buffer
442
443		logger := New(&LoggerOptions{
444			Name:   "test",
445			Output: NewLeveledWriter(&stdout, map[Level]io.Writer{Error: &stderr}),
446		})
447
448		logger.Info("this is test", "who", "programmer", "why", "testing")
449		logger.Error("this is an error", "who", "programmer", "why", "testing")
450
451		errStr := stderr.String()
452		errDataIdx := strings.IndexByte(errStr, ' ')
453		errRest := errStr[errDataIdx+1:]
454
455		outStr := stdout.String()
456		outDataIdx := strings.IndexByte(outStr, ' ')
457		outRest := outStr[outDataIdx+1:]
458
459		assert.Equal(t, "[ERROR] test: this is an error: who=programmer why=testing\n", errRest)
460		assert.Equal(t, "[INFO]  test: this is test: who=programmer why=testing\n", outRest)
461	})
462}
463
464func TestLogger_JSON(t *testing.T) {
465	t.Run("json formatting", func(t *testing.T) {
466		var buf bytes.Buffer
467		logger := New(&LoggerOptions{
468			Name:       "test",
469			Output:     &buf,
470			JSONFormat: true,
471		})
472
473		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
474
475		b := buf.Bytes()
476
477		var raw map[string]interface{}
478		if err := json.Unmarshal(b, &raw); err != nil {
479			t.Fatal(err)
480		}
481
482		assert.Equal(t, "this is test", raw["@message"])
483		assert.Equal(t, "programmer", raw["who"])
484		assert.Equal(t, "testing is fun", raw["why"])
485	})
486
487	t.Run("json formatting with", func(t *testing.T) {
488		var buf bytes.Buffer
489		logger := New(&LoggerOptions{
490			Name:       "test",
491			Output:     &buf,
492			JSONFormat: true,
493		})
494		logger = logger.With("cat", "in the hat", "dog", 42)
495
496		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
497
498		b := buf.Bytes()
499
500		var raw map[string]interface{}
501		if err := json.Unmarshal(b, &raw); err != nil {
502			t.Fatal(err)
503		}
504
505		assert.Equal(t, "this is test", raw["@message"])
506		assert.Equal(t, "programmer", raw["who"])
507		assert.Equal(t, "testing is fun", raw["why"])
508		assert.Equal(t, "in the hat", raw["cat"])
509		assert.Equal(t, float64(42), raw["dog"])
510	})
511
512	t.Run("json formatting error type", func(t *testing.T) {
513		var buf bytes.Buffer
514
515		logger := New(&LoggerOptions{
516			Name:       "test",
517			Output:     &buf,
518			JSONFormat: true,
519		})
520
521		errMsg := errors.New("this is an error")
522		logger.Info("this is test", "who", "programmer", "err", errMsg)
523
524		b := buf.Bytes()
525
526		var raw map[string]interface{}
527		if err := json.Unmarshal(b, &raw); err != nil {
528			t.Fatal(err)
529		}
530
531		assert.Equal(t, "this is test", raw["@message"])
532		assert.Equal(t, "programmer", raw["who"])
533		assert.Equal(t, errMsg.Error(), raw["err"])
534	})
535
536	t.Run("json formatting custom error type json marshaler", func(t *testing.T) {
537		var buf bytes.Buffer
538
539		logger := New(&LoggerOptions{
540			Name:       "test",
541			Output:     &buf,
542			JSONFormat: true,
543		})
544
545		errMsg := &customErrJSON{"this is an error"}
546		rawMsg, err := errMsg.MarshalJSON()
547		if err != nil {
548			t.Fatal(err)
549		}
550		expectedMsg, err := strconv.Unquote(string(rawMsg))
551		if err != nil {
552			t.Fatal(err)
553		}
554
555		logger.Info("this is test", "who", "programmer", "err", errMsg)
556
557		b := buf.Bytes()
558
559		var raw map[string]interface{}
560		if err := json.Unmarshal(b, &raw); err != nil {
561			t.Fatal(err)
562		}
563
564		assert.Equal(t, "this is test", raw["@message"])
565		assert.Equal(t, "programmer", raw["who"])
566		assert.Equal(t, expectedMsg, raw["err"])
567	})
568
569	t.Run("json formatting custom error type text marshaler", func(t *testing.T) {
570		var buf bytes.Buffer
571
572		logger := New(&LoggerOptions{
573			Name:       "test",
574			Output:     &buf,
575			JSONFormat: true,
576		})
577
578		errMsg := &customErrText{"this is an error"}
579		rawMsg, err := errMsg.MarshalText()
580		if err != nil {
581			t.Fatal(err)
582		}
583		expectedMsg := string(rawMsg)
584
585		logger.Info("this is test", "who", "programmer", "err", errMsg)
586
587		b := buf.Bytes()
588
589		var raw map[string]interface{}
590		if err := json.Unmarshal(b, &raw); err != nil {
591			t.Fatal(err)
592		}
593
594		assert.Equal(t, "this is test", raw["@message"])
595		assert.Equal(t, "programmer", raw["who"])
596		assert.Equal(t, expectedMsg, raw["err"])
597	})
598
599	t.Run("supports Printf style expansions when requested", func(t *testing.T) {
600		var buf bytes.Buffer
601
602		logger := New(&LoggerOptions{
603			Name:       "test",
604			Output:     &buf,
605			JSONFormat: true,
606		})
607
608		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
609
610		b := buf.Bytes()
611
612		var raw map[string]interface{}
613		if err := json.Unmarshal(b, &raw); err != nil {
614			t.Fatal(err)
615		}
616
617		assert.Equal(t, "this is test", raw["@message"])
618		assert.Equal(t, "12 beans/day", raw["production"])
619	})
620
621	t.Run("includes the caller location", func(t *testing.T) {
622		var buf bytes.Buffer
623
624		logger := New(&LoggerOptions{
625			Name:            "test",
626			Output:          &buf,
627			JSONFormat:      true,
628			IncludeLocation: true,
629		})
630
631		logger.Info("this is test")
632		_, file, line, ok := runtime.Caller(0)
633		require.True(t, ok)
634
635		b := buf.Bytes()
636
637		var raw map[string]interface{}
638		if err := json.Unmarshal(b, &raw); err != nil {
639			t.Fatal(err)
640		}
641
642		assert.Equal(t, "this is test", raw["@message"])
643		assert.Equal(t, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"])
644
645	})
646
647	t.Run("handles non-serializable entries", func(t *testing.T) {
648		var buf bytes.Buffer
649
650		logger := New(&LoggerOptions{
651			Name:       "test",
652			Output:     &buf,
653			JSONFormat: true,
654		})
655
656		myfunc := func() int { return 42 }
657		logger.Info("this is test", "production", myfunc)
658
659		b := buf.Bytes()
660
661		var raw map[string]interface{}
662		if err := json.Unmarshal(b, &raw); err != nil {
663			t.Fatal(err)
664		}
665
666		assert.Equal(t, "this is test", raw["@message"])
667		assert.Equal(t, errJsonUnsupportedTypeMsg, raw["@warn"])
668	})
669}
670
671type customErrJSON struct {
672	Message string
673}
674
675// error impl.
676func (c *customErrJSON) Error() string {
677	return c.Message
678}
679
680// json.Marshaler impl.
681func (c customErrJSON) MarshalJSON() ([]byte, error) {
682	return []byte(strconv.Quote(fmt.Sprintf("json-marshaler: %s", c.Message))), nil
683}
684
685type customErrText struct {
686	Message string
687}
688
689// error impl.
690func (c *customErrText) Error() string {
691	return c.Message
692}
693
694// text.Marshaler impl.
695func (c customErrText) MarshalText() ([]byte, error) {
696	return []byte(fmt.Sprintf("text-marshaler: %s", c.Message)), nil
697}
698
699func BenchmarkLogger(b *testing.B) {
700	b.Run("info with 10 pairs", func(b *testing.B) {
701		var buf bytes.Buffer
702
703		logger := New(&LoggerOptions{
704			Name:            "test",
705			Output:          &buf,
706			IncludeLocation: true,
707		})
708
709		for i := 0; i < b.N; i++ {
710			logger.Info("this is some message",
711				"name", "foo",
712				"what", "benchmarking yourself",
713				"why", "to see what's slow",
714				"k4", "value",
715				"k5", "value",
716				"k6", "value",
717				"k7", "value",
718				"k8", "value",
719				"k9", "value",
720				"k10", "value",
721			)
722		}
723	})
724}
725