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