1package logrus
2
3import (
4	"bytes"
5	"encoding/json"
6	"strconv"
7	"strings"
8	"sync"
9	"testing"
10	"time"
11
12	"github.com/stretchr/testify/assert"
13)
14
15func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) {
16	var buffer bytes.Buffer
17	var fields Fields
18
19	logger := New()
20	logger.Out = &buffer
21	logger.Formatter = new(JSONFormatter)
22
23	log(logger)
24
25	err := json.Unmarshal(buffer.Bytes(), &fields)
26	assert.Nil(t, err)
27
28	assertions(fields)
29}
30
31func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) {
32	var buffer bytes.Buffer
33
34	logger := New()
35	logger.Out = &buffer
36	logger.Formatter = &TextFormatter{
37		DisableColors: true,
38	}
39
40	log(logger)
41
42	fields := make(map[string]string)
43	for _, kv := range strings.Split(buffer.String(), " ") {
44		if !strings.Contains(kv, "=") {
45			continue
46		}
47		kvArr := strings.Split(kv, "=")
48		key := strings.TrimSpace(kvArr[0])
49		val := kvArr[1]
50		if kvArr[1][0] == '"' {
51			var err error
52			val, err = strconv.Unquote(val)
53			assert.NoError(t, err)
54		}
55		fields[key] = val
56	}
57	assertions(fields)
58}
59
60func TestPrint(t *testing.T) {
61	LogAndAssertJSON(t, func(log *Logger) {
62		log.Print("test")
63	}, func(fields Fields) {
64		assert.Equal(t, fields["msg"], "test")
65		assert.Equal(t, fields["level"], "info")
66	})
67}
68
69func TestInfo(t *testing.T) {
70	LogAndAssertJSON(t, func(log *Logger) {
71		log.Info("test")
72	}, func(fields Fields) {
73		assert.Equal(t, fields["msg"], "test")
74		assert.Equal(t, fields["level"], "info")
75	})
76}
77
78func TestWarn(t *testing.T) {
79	LogAndAssertJSON(t, func(log *Logger) {
80		log.Warn("test")
81	}, func(fields Fields) {
82		assert.Equal(t, fields["msg"], "test")
83		assert.Equal(t, fields["level"], "warning")
84	})
85}
86
87func TestInfolnShouldAddSpacesBetweenStrings(t *testing.T) {
88	LogAndAssertJSON(t, func(log *Logger) {
89		log.Infoln("test", "test")
90	}, func(fields Fields) {
91		assert.Equal(t, fields["msg"], "test test")
92	})
93}
94
95func TestInfolnShouldAddSpacesBetweenStringAndNonstring(t *testing.T) {
96	LogAndAssertJSON(t, func(log *Logger) {
97		log.Infoln("test", 10)
98	}, func(fields Fields) {
99		assert.Equal(t, fields["msg"], "test 10")
100	})
101}
102
103func TestInfolnShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
104	LogAndAssertJSON(t, func(log *Logger) {
105		log.Infoln(10, 10)
106	}, func(fields Fields) {
107		assert.Equal(t, fields["msg"], "10 10")
108	})
109}
110
111func TestInfoShouldAddSpacesBetweenTwoNonStrings(t *testing.T) {
112	LogAndAssertJSON(t, func(log *Logger) {
113		log.Infoln(10, 10)
114	}, func(fields Fields) {
115		assert.Equal(t, fields["msg"], "10 10")
116	})
117}
118
119func TestInfoShouldNotAddSpacesBetweenStringAndNonstring(t *testing.T) {
120	LogAndAssertJSON(t, func(log *Logger) {
121		log.Info("test", 10)
122	}, func(fields Fields) {
123		assert.Equal(t, fields["msg"], "test10")
124	})
125}
126
127func TestInfoShouldNotAddSpacesBetweenStrings(t *testing.T) {
128	LogAndAssertJSON(t, func(log *Logger) {
129		log.Info("test", "test")
130	}, func(fields Fields) {
131		assert.Equal(t, fields["msg"], "testtest")
132	})
133}
134
135func TestWithFieldsShouldAllowAssignments(t *testing.T) {
136	var buffer bytes.Buffer
137	var fields Fields
138
139	logger := New()
140	logger.Out = &buffer
141	logger.Formatter = new(JSONFormatter)
142
143	localLog := logger.WithFields(Fields{
144		"key1": "value1",
145	})
146
147	localLog.WithField("key2", "value2").Info("test")
148	err := json.Unmarshal(buffer.Bytes(), &fields)
149	assert.Nil(t, err)
150
151	assert.Equal(t, "value2", fields["key2"])
152	assert.Equal(t, "value1", fields["key1"])
153
154	buffer = bytes.Buffer{}
155	fields = Fields{}
156	localLog.Info("test")
157	err = json.Unmarshal(buffer.Bytes(), &fields)
158	assert.Nil(t, err)
159
160	_, ok := fields["key2"]
161	assert.Equal(t, false, ok)
162	assert.Equal(t, "value1", fields["key1"])
163}
164
165func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) {
166	LogAndAssertJSON(t, func(log *Logger) {
167		log.WithField("msg", "hello").Info("test")
168	}, func(fields Fields) {
169		assert.Equal(t, fields["msg"], "test")
170	})
171}
172
173func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) {
174	LogAndAssertJSON(t, func(log *Logger) {
175		log.WithField("msg", "hello").Info("test")
176	}, func(fields Fields) {
177		assert.Equal(t, fields["msg"], "test")
178		assert.Equal(t, fields["fields.msg"], "hello")
179	})
180}
181
182func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) {
183	LogAndAssertJSON(t, func(log *Logger) {
184		log.WithField("time", "hello").Info("test")
185	}, func(fields Fields) {
186		assert.Equal(t, fields["fields.time"], "hello")
187	})
188}
189
190func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) {
191	LogAndAssertJSON(t, func(log *Logger) {
192		log.WithField("level", 1).Info("test")
193	}, func(fields Fields) {
194		assert.Equal(t, fields["level"], "info")
195		assert.Equal(t, fields["fields.level"], 1.0) // JSON has floats only
196	})
197}
198
199func TestDefaultFieldsAreNotPrefixed(t *testing.T) {
200	LogAndAssertText(t, func(log *Logger) {
201		ll := log.WithField("herp", "derp")
202		ll.Info("hello")
203		ll.Info("bye")
204	}, func(fields map[string]string) {
205		for _, fieldName := range []string{"fields.level", "fields.time", "fields.msg"} {
206			if _, ok := fields[fieldName]; ok {
207				t.Fatalf("should not have prefixed %q: %v", fieldName, fields)
208			}
209		}
210	})
211}
212
213func TestWithTimeShouldOverrideTime(t *testing.T) {
214	now := time.Now().Add(24 * time.Hour)
215
216	LogAndAssertJSON(t, func(log *Logger) {
217		log.WithTime(now).Info("foobar")
218	}, func(fields Fields) {
219		assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
220	})
221}
222
223func TestWithTimeShouldNotOverrideFields(t *testing.T) {
224	now := time.Now().Add(24 * time.Hour)
225
226	LogAndAssertJSON(t, func(log *Logger) {
227		log.WithField("herp", "derp").WithTime(now).Info("blah")
228	}, func(fields Fields) {
229		assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
230		assert.Equal(t, fields["herp"], "derp")
231	})
232}
233
234func TestWithFieldShouldNotOverrideTime(t *testing.T) {
235	now := time.Now().Add(24 * time.Hour)
236
237	LogAndAssertJSON(t, func(log *Logger) {
238		log.WithTime(now).WithField("herp", "derp").Info("blah")
239	}, func(fields Fields) {
240		assert.Equal(t, fields["time"], now.Format(defaultTimestampFormat))
241		assert.Equal(t, fields["herp"], "derp")
242	})
243}
244
245func TestTimeOverrideMultipleLogs(t *testing.T) {
246	var buffer bytes.Buffer
247	var firstFields, secondFields Fields
248
249	logger := New()
250	logger.Out = &buffer
251	formatter := new(JSONFormatter)
252	formatter.TimestampFormat = time.StampMilli
253	logger.Formatter = formatter
254
255	llog := logger.WithField("herp", "derp")
256	llog.Info("foo")
257
258	err := json.Unmarshal(buffer.Bytes(), &firstFields)
259	assert.NoError(t, err, "should have decoded first message")
260
261	buffer.Reset()
262
263	time.Sleep(10 * time.Millisecond)
264	llog.Info("bar")
265
266	err = json.Unmarshal(buffer.Bytes(), &secondFields)
267	assert.NoError(t, err, "should have decoded second message")
268
269	assert.NotEqual(t, firstFields["time"], secondFields["time"], "timestamps should not be equal")
270}
271
272func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) {
273
274	var buffer bytes.Buffer
275	var fields Fields
276
277	logger := New()
278	logger.Out = &buffer
279	logger.Formatter = new(JSONFormatter)
280
281	llog := logger.WithField("context", "eating raw fish")
282
283	llog.Info("looks delicious")
284
285	err := json.Unmarshal(buffer.Bytes(), &fields)
286	assert.NoError(t, err, "should have decoded first message")
287	assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
288	assert.Equal(t, fields["msg"], "looks delicious")
289	assert.Equal(t, fields["context"], "eating raw fish")
290
291	buffer.Reset()
292
293	llog.Warn("omg it is!")
294
295	err = json.Unmarshal(buffer.Bytes(), &fields)
296	assert.NoError(t, err, "should have decoded second message")
297	assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
298	assert.Equal(t, fields["msg"], "omg it is!")
299	assert.Equal(t, fields["context"], "eating raw fish")
300	assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
301
302}
303
304func TestConvertLevelToString(t *testing.T) {
305	assert.Equal(t, "debug", DebugLevel.String())
306	assert.Equal(t, "info", InfoLevel.String())
307	assert.Equal(t, "warning", WarnLevel.String())
308	assert.Equal(t, "error", ErrorLevel.String())
309	assert.Equal(t, "fatal", FatalLevel.String())
310	assert.Equal(t, "panic", PanicLevel.String())
311}
312
313func TestParseLevel(t *testing.T) {
314	l, err := ParseLevel("panic")
315	assert.Nil(t, err)
316	assert.Equal(t, PanicLevel, l)
317
318	l, err = ParseLevel("PANIC")
319	assert.Nil(t, err)
320	assert.Equal(t, PanicLevel, l)
321
322	l, err = ParseLevel("fatal")
323	assert.Nil(t, err)
324	assert.Equal(t, FatalLevel, l)
325
326	l, err = ParseLevel("FATAL")
327	assert.Nil(t, err)
328	assert.Equal(t, FatalLevel, l)
329
330	l, err = ParseLevel("error")
331	assert.Nil(t, err)
332	assert.Equal(t, ErrorLevel, l)
333
334	l, err = ParseLevel("ERROR")
335	assert.Nil(t, err)
336	assert.Equal(t, ErrorLevel, l)
337
338	l, err = ParseLevel("warn")
339	assert.Nil(t, err)
340	assert.Equal(t, WarnLevel, l)
341
342	l, err = ParseLevel("WARN")
343	assert.Nil(t, err)
344	assert.Equal(t, WarnLevel, l)
345
346	l, err = ParseLevel("warning")
347	assert.Nil(t, err)
348	assert.Equal(t, WarnLevel, l)
349
350	l, err = ParseLevel("WARNING")
351	assert.Nil(t, err)
352	assert.Equal(t, WarnLevel, l)
353
354	l, err = ParseLevel("info")
355	assert.Nil(t, err)
356	assert.Equal(t, InfoLevel, l)
357
358	l, err = ParseLevel("INFO")
359	assert.Nil(t, err)
360	assert.Equal(t, InfoLevel, l)
361
362	l, err = ParseLevel("debug")
363	assert.Nil(t, err)
364	assert.Equal(t, DebugLevel, l)
365
366	l, err = ParseLevel("DEBUG")
367	assert.Nil(t, err)
368	assert.Equal(t, DebugLevel, l)
369
370	l, err = ParseLevel("invalid")
371	assert.Equal(t, "not a valid logrus Level: \"invalid\"", err.Error())
372}
373
374func TestGetSetLevelRace(t *testing.T) {
375	wg := sync.WaitGroup{}
376	for i := 0; i < 100; i++ {
377		wg.Add(1)
378		go func(i int) {
379			defer wg.Done()
380			if i%2 == 0 {
381				SetLevel(InfoLevel)
382			} else {
383				GetLevel()
384			}
385		}(i)
386
387	}
388	wg.Wait()
389}
390
391func TestLoggingRace(t *testing.T) {
392	logger := New()
393
394	var wg sync.WaitGroup
395	wg.Add(100)
396
397	for i := 0; i < 100; i++ {
398		go func() {
399			logger.Info("info")
400			wg.Done()
401		}()
402	}
403	wg.Wait()
404}
405
406// Compile test
407func TestLogrusInterface(t *testing.T) {
408	var buffer bytes.Buffer
409	fn := func(l FieldLogger) {
410		b := l.WithField("key", "value")
411		b.Debug("Test")
412	}
413	// test logger
414	logger := New()
415	logger.Out = &buffer
416	fn(logger)
417
418	// test Entry
419	e := logger.WithField("another", "value")
420	fn(e)
421}
422
423// Implements io.Writer using channels for synchronization, so we can wait on
424// the Entry.Writer goroutine to write in a non-racey way. This does assume that
425// there is a single call to Logger.Out for each message.
426type channelWriter chan []byte
427
428func (cw channelWriter) Write(p []byte) (int, error) {
429	cw <- p
430	return len(p), nil
431}
432
433func TestEntryWriter(t *testing.T) {
434	cw := channelWriter(make(chan []byte, 1))
435	log := New()
436	log.Out = cw
437	log.Formatter = new(JSONFormatter)
438	log.WithField("foo", "bar").WriterLevel(WarnLevel).Write([]byte("hello\n"))
439
440	bs := <-cw
441	var fields Fields
442	err := json.Unmarshal(bs, &fields)
443	assert.Nil(t, err)
444	assert.Equal(t, fields["foo"], "bar")
445	assert.Equal(t, fields["level"], "warning")
446}
447