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