1package hclog
2
3import (
4	"bytes"
5	"encoding/json"
6	"fmt"
7	"runtime"
8	"strings"
9	"testing"
10
11	"github.com/stretchr/testify/assert"
12	"github.com/stretchr/testify/require"
13)
14
15func TestInterceptLogger(t *testing.T) {
16	t.Run("sends output to registered sinks", func(t *testing.T) {
17		var buf bytes.Buffer
18		var sbuf bytes.Buffer
19
20		intercept := NewInterceptLogger(&LoggerOptions{
21			Level:  Info,
22			Output: &buf,
23		})
24
25		sink := NewSinkAdapter(&LoggerOptions{
26			Level:  Debug,
27			Output: &sbuf,
28		})
29
30		intercept.RegisterSink(sink)
31		defer intercept.DeregisterSink(sink)
32
33		intercept.Debug("test log", "who", "programmer")
34
35		str := sbuf.String()
36		dataIdx := strings.IndexByte(str, ' ')
37		rest := str[dataIdx+1:]
38
39		assert.Equal(t, "[DEBUG] test log: who=programmer\n", rest)
40
41	})
42
43	t.Run("sink includes with arguments", func(t *testing.T) {
44		var buf bytes.Buffer
45		var sbuf bytes.Buffer
46
47		intercept := NewInterceptLogger(&LoggerOptions{
48			Name:   "with_test",
49			Level:  Info,
50			Output: &buf,
51		})
52
53		sink := NewSinkAdapter(&LoggerOptions{
54			Level:  Debug,
55			Output: &sbuf,
56		})
57		intercept.RegisterSink(sink)
58		defer intercept.DeregisterSink(sink)
59
60		derived := intercept.With("a", 1, "b", 2)
61		derived = derived.With("c", 3)
62
63		derived.Info("test1")
64		output := buf.String()
65		dataIdx := strings.IndexByte(output, ' ')
66		rest := output[dataIdx+1:]
67
68		assert.Equal(t, "[INFO]  with_test: test1: a=1 b=2 c=3\n", rest)
69
70		// Ensure intercept works
71		output = sbuf.String()
72		dataIdx = strings.IndexByte(output, ' ')
73		rest = output[dataIdx+1:]
74
75		assert.Equal(t, "[INFO]  with_test: test1: a=1 b=2 c=3\n", rest)
76	})
77
78	t.Run("sink includes name", func(t *testing.T) {
79		var buf bytes.Buffer
80		var sbuf bytes.Buffer
81
82		intercept := NewInterceptLogger(&LoggerOptions{
83			Name:   "with_test",
84			Level:  Info,
85			Output: &buf,
86		})
87
88		sink := NewSinkAdapter(&LoggerOptions{
89			Level:  Debug,
90			Output: &sbuf,
91		})
92		intercept.RegisterSink(sink)
93		defer intercept.DeregisterSink(sink)
94
95		httpLogger := intercept.Named("http")
96
97		httpLogger.Info("test1")
98		output := buf.String()
99		dataIdx := strings.IndexByte(output, ' ')
100		rest := output[dataIdx+1:]
101
102		assert.Equal(t, "[INFO]  with_test.http: test1\n", rest)
103
104		// Ensure intercept works
105		output = sbuf.String()
106		dataIdx = strings.IndexByte(output, ' ')
107		rest = output[dataIdx+1:]
108
109		assert.Equal(t, "[INFO]  with_test.http: test1\n", rest)
110	})
111
112	t.Run("intercepting logger can create logger with reset name", func(t *testing.T) {
113		var buf bytes.Buffer
114		var sbuf bytes.Buffer
115
116		intercept := NewInterceptLogger(&LoggerOptions{
117			Name:   "with_test",
118			Level:  Info,
119			Output: &buf,
120		})
121
122		sink := NewSinkAdapter(&LoggerOptions{
123			Level:  Debug,
124			Output: &sbuf,
125		})
126		intercept.RegisterSink(sink)
127		defer intercept.DeregisterSink(sink)
128
129		httpLogger := intercept.ResetNamed("http")
130
131		httpLogger.Info("test1")
132		output := buf.String()
133		dataIdx := strings.IndexByte(output, ' ')
134		rest := output[dataIdx+1:]
135
136		assert.Equal(t, "[INFO]  http: test1\n", rest)
137
138		// Ensure intercept works
139		output = sbuf.String()
140		dataIdx = strings.IndexByte(output, ' ')
141		rest = output[dataIdx+1:]
142
143		assert.Equal(t, "[INFO]  http: test1\n", rest)
144	})
145
146	t.Run("Intercepting logger sink can deregister itself", func(t *testing.T) {
147		var buf bytes.Buffer
148		var sbuf bytes.Buffer
149
150		intercept := NewInterceptLogger(&LoggerOptions{
151			Name:   "with_test",
152			Level:  Info,
153			Output: &buf,
154		})
155
156		sink := NewSinkAdapter(&LoggerOptions{
157			Level:  Debug,
158			Output: &sbuf,
159		})
160		intercept.RegisterSink(sink)
161		intercept.DeregisterSink(sink)
162
163		intercept.Info("test1")
164
165		assert.Equal(t, "", sbuf.String())
166	})
167
168	t.Run("Sinks accept different log formats", func(t *testing.T) {
169		var buf bytes.Buffer
170		var sbuf bytes.Buffer
171
172		intercept := NewInterceptLogger(&LoggerOptions{
173			Level:           Info,
174			Output:          &buf,
175			IncludeLocation: true,
176		})
177
178		sink := NewSinkAdapter(&LoggerOptions{
179			Level:           Debug,
180			Output:          &sbuf,
181			JSONFormat:      true,
182			IncludeLocation: true,
183		})
184
185		intercept.RegisterSink(sink)
186		defer intercept.DeregisterSink(sink)
187
188		intercept.Info("this is a test", "who", "caller")
189		_, file, line, ok := runtime.Caller(0)
190		require.True(t, ok)
191
192		output := buf.String()
193		dataIdx := strings.IndexByte(output, ' ')
194		rest := output[dataIdx+1:]
195
196		expected := fmt.Sprintf("[INFO]  go-hclog/interceptlogger_test.go:%d: this is a test: who=caller\n", line-1)
197		assert.Equal(t, expected, rest)
198
199		b := sbuf.Bytes()
200
201		var raw map[string]interface{}
202		if err := json.Unmarshal(b, &raw); err != nil {
203			t.Fatal(err)
204		}
205
206		assert.Equal(t, "this is a test", raw["@message"])
207		assert.Equal(t, "caller", raw["who"])
208		assert.Equal(t, fmt.Sprintf("%v:%d", file, line-1), raw["@caller"])
209	})
210
211	t.Run("handles parent with arguments and log level args", func(t *testing.T) {
212		var buf bytes.Buffer
213		var sbuf bytes.Buffer
214
215		intercept := NewInterceptLogger(&LoggerOptions{
216			Name:   "with_test",
217			Level:  Debug,
218			Output: &buf,
219		})
220
221		sink := NewSinkAdapter(&LoggerOptions{
222			Level:  Debug,
223			Output: &sbuf,
224		})
225		intercept.RegisterSink(sink)
226		defer intercept.DeregisterSink(sink)
227
228		named := intercept.Named("sub_logger")
229		named = named.With("parent", "logger")
230		subNamed := named.Named("http")
231
232		subNamed.Debug("test1", "path", "/some/test/path", "args", []string{"test", "test"})
233
234		output := buf.String()
235		dataIdx := strings.IndexByte(output, ' ')
236		rest := output[dataIdx+1:]
237		assert.Equal(t, "[DEBUG] with_test.sub_logger.http: test1: parent=logger path=/some/test/path args=[\"test\", \"test\"]\n", rest)
238	})
239
240	t.Run("derived standard loggers send output to sinks", func(t *testing.T) {
241		var buf bytes.Buffer
242		var sbuf bytes.Buffer
243
244		intercept := NewInterceptLogger(&LoggerOptions{
245			Name:   "with_name",
246			Level:  Debug,
247			Output: &buf,
248		})
249
250		standard := intercept.StandardLogger(&StandardLoggerOptions{InferLevels: true})
251
252		sink := NewSinkAdapter(&LoggerOptions{
253			Level:  Debug,
254			Output: &sbuf,
255		})
256		intercept.RegisterSink(sink)
257		defer intercept.DeregisterSink(sink)
258
259		standard.Println("[DEBUG] test log")
260
261		output := buf.String()
262		dataIdx := strings.IndexByte(output, ' ')
263		rest := output[dataIdx+1:]
264		assert.Equal(t, "[DEBUG] with_name: test log\n", rest)
265
266		output = sbuf.String()
267		dataIdx = strings.IndexByte(output, ' ')
268		rest = output[dataIdx+1:]
269		assert.Equal(t, "[DEBUG] with_name: test log\n", rest)
270	})
271
272	t.Run("includes the caller location", func(t *testing.T) {
273		var buf bytes.Buffer
274		var sbuf bytes.Buffer
275
276		logger := NewInterceptLogger(&LoggerOptions{
277			Name:            "test",
278			Output:          &buf,
279			IncludeLocation: true,
280		})
281
282		sink := NewSinkAdapter(&LoggerOptions{
283			IncludeLocation: true,
284			Level:           Debug,
285			Output:          &sbuf,
286		})
287		logger.RegisterSink(sink)
288		defer logger.DeregisterSink(sink)
289
290		logger.Info("this is test", "who", "programmer", "why", "testing is fun")
291		_, _, line, ok := runtime.Caller(0)
292		require.True(t, ok)
293
294		str := buf.String()
295		dataIdx := strings.IndexByte(str, ' ')
296		rest := str[dataIdx+1:]
297
298		expected := fmt.Sprintf("[INFO]  go-hclog/interceptlogger_test.go:%d: test: this is test: who=programmer why=\"testing is fun\"\n", line-1)
299		assert.Equal(t, expected, rest)
300
301		str = sbuf.String()
302		dataIdx = strings.IndexByte(str, ' ')
303		rest = str[dataIdx+1:]
304		assert.Equal(t, expected, rest)
305	})
306
307	t.Run("supports resetting the output", func(t *testing.T) {
308		var first, second bytes.Buffer
309
310		logger := NewInterceptLogger(&LoggerOptions{
311			Output: &first,
312		})
313
314		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
315
316		str := first.String()
317		dataIdx := strings.IndexByte(str, ' ')
318		rest := str[dataIdx+1:]
319
320		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
321
322		logger.(OutputResettable).ResetOutput(&LoggerOptions{
323			Output: &second,
324		})
325
326		logger.Info("this is another test", "production", Fmt("%d beans/day", 13))
327
328		str = first.String()
329		dataIdx = strings.IndexByte(str, ' ')
330		rest = str[dataIdx+1:]
331		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
332
333		str = second.String()
334		dataIdx = strings.IndexByte(str, ' ')
335		rest = str[dataIdx+1:]
336		assert.Equal(t, "[INFO]  this is another test: production=\"13 beans/day\"\n", rest)
337	})
338
339	t.Run("supports resetting the output with flushing", func(t *testing.T) {
340		var first bufferingBuffer
341		var second bytes.Buffer
342
343		logger := NewInterceptLogger(&LoggerOptions{
344			Output: &first,
345		})
346
347		logger.Info("this is test", "production", Fmt("%d beans/day", 12))
348
349		str := first.String()
350		assert.Empty(t, str)
351
352		logger.(OutputResettable).ResetOutputWithFlush(&LoggerOptions{
353			Output: &second,
354		}, &first)
355
356		logger.Info("this is another test", "production", Fmt("%d beans/day", 13))
357
358		str = first.String()
359		dataIdx := strings.IndexByte(str, ' ')
360		rest := str[dataIdx+1:]
361		assert.Equal(t, "[INFO]  this is test: production=\"12 beans/day\"\n", rest)
362
363		str = second.String()
364		dataIdx = strings.IndexByte(str, ' ')
365		rest = str[dataIdx+1:]
366		assert.Equal(t, "[INFO]  this is another test: production=\"13 beans/day\"\n", rest)
367	})
368}
369