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