github.com/Laisky/zap@v1.27.0/logger_test.go (about) 1 // Copyright (c) 2016 Uber Technologies, Inc. 2 // 3 // Permission is hereby granted, free of charge, to any person obtaining a copy 4 // of this software and associated documentation files (the "Software"), to deal 5 // in the Software without restriction, including without limitation the rights 6 // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell 7 // copies of the Software, and to permit persons to whom the Software is 8 // furnished to do so, subject to the following conditions: 9 // 10 // The above copyright notice and this permission notice shall be included in 11 // all copies or substantial portions of the Software. 12 // 13 // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR 14 // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, 15 // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE 16 // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER 17 // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, 18 // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN 19 // THE SOFTWARE. 20 21 package zap 22 23 import ( 24 "errors" 25 "fmt" 26 "strconv" 27 "sync" 28 "sync/atomic" 29 "testing" 30 31 "github.com/Laisky/zap/internal/exit" 32 "github.com/Laisky/zap/internal/ztest" 33 "github.com/Laisky/zap/zapcore" 34 "github.com/Laisky/zap/zaptest/observer" 35 36 "github.com/stretchr/testify/assert" 37 "github.com/stretchr/testify/require" 38 ) 39 40 func makeCountingHook() (func(zapcore.Entry) error, *atomic.Int64) { 41 count := &atomic.Int64{} 42 h := func(zapcore.Entry) error { 43 count.Add(1) 44 return nil 45 } 46 return h, count 47 } 48 49 func makeCountingHookWithFields() (func(zapcore.Entry, []zapcore.Field) error, *atomic.Int64) { 50 count := &atomic.Int64{} 51 h := func(zapcore.Entry, []zapcore.Field) error { 52 count.Add(1) 53 return nil 54 } 55 return h, count 56 } 57 58 func TestLoggerAtomicLevel(t *testing.T) { 59 // Test that the dynamic level applies to all ancestors and descendants. 60 dl := NewAtomicLevel() 61 62 withLogger(t, dl, nil, func(grandparent *Logger, _ *observer.ObservedLogs) { 63 parent := grandparent.With(Int("generation", 1)) 64 child := parent.With(Int("generation", 2)) 65 66 tests := []struct { 67 setLevel zapcore.Level 68 testLevel zapcore.Level 69 enabled bool 70 }{ 71 {DebugLevel, DebugLevel, true}, 72 {InfoLevel, DebugLevel, false}, 73 {WarnLevel, PanicLevel, true}, 74 } 75 76 for _, tt := range tests { 77 dl.SetLevel(tt.setLevel) 78 for _, logger := range []*Logger{grandparent, parent, child} { 79 if tt.enabled { 80 assert.NotNil( 81 t, 82 logger.Check(tt.testLevel, ""), 83 "Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel, 84 ) 85 } else { 86 assert.Nil( 87 t, 88 logger.Check(tt.testLevel, ""), 89 "Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel, 90 ) 91 } 92 } 93 } 94 }) 95 } 96 97 func TestLoggerLevel(t *testing.T) { 98 levels := []zapcore.Level{ 99 DebugLevel, 100 InfoLevel, 101 WarnLevel, 102 ErrorLevel, 103 DPanicLevel, 104 PanicLevel, 105 FatalLevel, 106 } 107 108 for _, lvl := range levels { 109 lvl := lvl 110 t.Run(lvl.String(), func(t *testing.T) { 111 t.Parallel() 112 113 core, _ := observer.New(lvl) 114 log := New(core) 115 assert.Equal(t, lvl, log.Level()) 116 }) 117 } 118 119 t.Run("Nop", func(t *testing.T) { 120 assert.Equal(t, zapcore.InvalidLevel, NewNop().Level()) 121 }) 122 } 123 124 func TestLoggerInitialFields(t *testing.T) { 125 fieldOpts := opts(Fields(Int("foo", 42), String("bar", "baz"))) 126 withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { 127 logger.Info("") 128 assert.Equal( 129 t, 130 observer.LoggedEntry{Context: []Field{Int("foo", 42), String("bar", "baz")}}, 131 logs.AllUntimed()[0], 132 "Unexpected output with initial fields set.", 133 ) 134 }) 135 } 136 137 func TestLoggerWith(t *testing.T) { 138 tests := []struct { 139 name string 140 initialFields []Field 141 withMethod func(*Logger, ...Field) *Logger 142 }{ 143 { 144 "regular non lazy logger", 145 []Field{Int("foo", 42)}, 146 (*Logger).With, 147 }, 148 { 149 "regular non lazy logger no initial fields", 150 []Field{}, 151 (*Logger).With, 152 }, 153 { 154 "lazy with logger", 155 []Field{Int("foo", 42)}, 156 (*Logger).WithLazy, 157 }, 158 { 159 "lazy with logger no initial fields", 160 []Field{}, 161 (*Logger).WithLazy, 162 }, 163 } 164 for _, tt := range tests { 165 t.Run(tt.name, func(t *testing.T) { 166 withLogger(t, DebugLevel, opts(Fields(tt.initialFields...)), func(logger *Logger, logs *observer.ObservedLogs) { 167 // Child loggers should have copy-on-write semantics, so two children 168 // shouldn't stomp on each other's fields or affect the parent's fields. 169 tt.withMethod(logger).Info("") 170 tt.withMethod(logger, String("one", "two")).Info("") 171 tt.withMethod(logger, String("three", "four")).Info("") 172 tt.withMethod(logger, String("five", "six")).With(String("seven", "eight")).Info("") 173 logger.Info("") 174 175 assert.Equal(t, []observer.LoggedEntry{ 176 {Context: tt.initialFields}, 177 {Context: append(tt.initialFields, String("one", "two"))}, 178 {Context: append(tt.initialFields, String("three", "four"))}, 179 {Context: append(tt.initialFields, String("five", "six"), String("seven", "eight"))}, 180 {Context: tt.initialFields}, 181 }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") 182 }) 183 }) 184 } 185 } 186 187 func TestLoggerWithCaptures(t *testing.T) { 188 type withF func(*Logger, ...Field) *Logger 189 tests := []struct { 190 name string 191 withMethods []withF 192 wantJSON []string 193 }{ 194 { 195 name: "regular with captures arguments at time of With", 196 withMethods: []withF{(*Logger).With}, 197 wantJSON: []string{ 198 `{ 199 "m": "hello 0", 200 "a0": [0], 201 "b0": [1] 202 }`, 203 `{ 204 "m": "world 0", 205 "a0": [0], 206 "c0": [2] 207 }`, 208 }, 209 }, 210 { 211 name: "lazy with captures arguments at time of With or Logging", 212 withMethods: []withF{(*Logger).WithLazy}, 213 wantJSON: []string{ 214 `{ 215 "m": "hello 0", 216 "a0": [1], 217 "b0": [1] 218 }`, 219 `{ 220 "m": "world 0", 221 "a0": [1], 222 "c0": [2] 223 }`, 224 }, 225 }, 226 { 227 name: "2x With captures arguments at time of each With", 228 withMethods: []withF{(*Logger).With, (*Logger).With}, 229 wantJSON: []string{ 230 `{ 231 "m": "hello 0", 232 "a0": [0], 233 "b0": [1] 234 }`, 235 `{ 236 "m": "world 0", 237 "a0": [0], 238 "c0": [2] 239 }`, 240 `{ 241 "m": "hello 1", 242 "a0": [0], 243 "c0": [2], 244 "a1": [10], 245 "b1": [11] 246 }`, 247 `{ 248 "m": "world 1", 249 "a0": [0], 250 "c0": [2], 251 "a1": [10], 252 "c1": [12] 253 }`, 254 }, 255 }, 256 { 257 name: "2x WithLazy. Captures arguments only at logging time.", 258 withMethods: []withF{(*Logger).WithLazy, (*Logger).WithLazy}, 259 wantJSON: []string{ 260 `{ 261 "m": "hello 0", 262 "a0": [1], 263 "b0": [1] 264 }`, 265 `{ 266 "m": "world 0", 267 "a0": [1], 268 "c0": [2] 269 }`, 270 `{ 271 "m": "hello 1", 272 "a0": [1], 273 "c0": [2], 274 "a1": [11], 275 "b1": [11] 276 }`, 277 `{ 278 "m": "world 1", 279 "a0": [1], 280 "c0": [2], 281 "a1": [11], 282 "c1": [12] 283 }`, 284 }, 285 }, 286 { 287 name: "WithLazy then With", 288 withMethods: []withF{(*Logger).WithLazy, (*Logger).With}, 289 wantJSON: []string{ 290 `{ 291 "m": "hello 0", 292 "a0": [1], 293 "b0": [1] 294 }`, 295 `{ 296 "m": "world 0", 297 "a0": [1], 298 "c0": [2] 299 }`, 300 `{ 301 "m": "hello 1", 302 "a0": [1], 303 "c0": [2], 304 "a1": [10], 305 "b1": [11] 306 }`, 307 `{ 308 "m": "world 1", 309 "a0": [1], 310 "c0": [2], 311 "a1": [10], 312 "c1": [12] 313 }`, 314 }, 315 }, 316 { 317 name: "With then WithLazy", 318 withMethods: []withF{(*Logger).With, (*Logger).WithLazy}, 319 wantJSON: []string{ 320 `{ 321 "m": "hello 0", 322 "a0": [0], 323 "b0": [1] 324 }`, 325 `{ 326 "m": "world 0", 327 "a0": [0], 328 "c0": [2] 329 }`, 330 `{ 331 "m": "hello 1", 332 "a0": [0], 333 "c0": [2], 334 "a1": [11], 335 "b1": [11] 336 }`, 337 `{ 338 "m": "world 1", 339 "a0": [0], 340 "c0": [2], 341 "a1": [11], 342 "c1": [12] 343 }`, 344 }, 345 }, 346 } 347 348 for _, tt := range tests { 349 t.Run(tt.name, func(t *testing.T) { 350 enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ 351 MessageKey: "m", 352 }) 353 354 var bs ztest.Buffer 355 logger := New(zapcore.NewCore(enc, &bs, DebugLevel)) 356 357 for i, withMethod := range tt.withMethods { 358 359 iStr := strconv.Itoa(i) 360 x := 10 * i 361 arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { 362 enc.AppendInt(x) 363 return nil 364 }) 365 366 // Demonstrate the arguments are captured when With() and Info() are invoked. 367 logger = withMethod(logger, Array("a"+iStr, arr)) 368 x++ 369 logger.Info(fmt.Sprintf("hello %d", i), Array("b"+iStr, arr)) 370 x++ 371 logger = withMethod(logger, Array("c"+iStr, arr)) 372 logger.Info(fmt.Sprintf("world %d", i)) 373 } 374 375 if lines := bs.Lines(); assert.Len(t, lines, len(tt.wantJSON)) { 376 for i, want := range tt.wantJSON { 377 assert.JSONEq(t, want, lines[i], "Unexpected output from the %d'th log.", i) 378 } 379 } 380 }) 381 } 382 } 383 384 func TestLoggerLogPanic(t *testing.T) { 385 for _, tt := range []struct { 386 do func(*Logger) 387 should bool 388 expected string 389 }{ 390 {func(logger *Logger) { logger.Check(PanicLevel, "foo").Write() }, true, "foo"}, 391 {func(logger *Logger) { logger.Log(PanicLevel, "bar") }, true, "bar"}, 392 {func(logger *Logger) { logger.Panic("baz") }, true, "baz"}, 393 } { 394 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 395 if tt.should { 396 assert.Panics(t, func() { tt.do(logger) }, "Expected panic") 397 } else { 398 assert.NotPanics(t, func() { tt.do(logger) }, "Expected no panic") 399 } 400 401 output := logs.AllUntimed() 402 assert.Equal(t, 1, len(output), "Unexpected number of logs.") 403 assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.") 404 assert.Equal( 405 t, 406 zapcore.Entry{Message: tt.expected, Level: PanicLevel}, 407 output[0].Entry, 408 "Unexpected output from panic-level Log.", 409 ) 410 }) 411 } 412 } 413 414 func TestLoggerLogFatal(t *testing.T) { 415 for _, tt := range []struct { 416 do func(*Logger) 417 expected string 418 }{ 419 {func(logger *Logger) { logger.Check(FatalLevel, "foo").Write() }, "foo"}, 420 {func(logger *Logger) { logger.Log(FatalLevel, "bar") }, "bar"}, 421 {func(logger *Logger) { logger.Fatal("baz") }, "baz"}, 422 } { 423 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 424 stub := exit.WithStub(func() { 425 tt.do(logger) 426 }) 427 assert.True(t, stub.Exited, "Expected Fatal logger call to terminate process.") 428 output := logs.AllUntimed() 429 assert.Equal(t, 1, len(output), "Unexpected number of logs.") 430 assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.") 431 assert.Equal( 432 t, 433 zapcore.Entry{Message: tt.expected, Level: FatalLevel}, 434 output[0].Entry, 435 "Unexpected output from fatal-level Log.", 436 ) 437 }) 438 } 439 } 440 441 func TestLoggerLeveledMethods(t *testing.T) { 442 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 443 tests := []struct { 444 method func(string, ...Field) 445 expectedLevel zapcore.Level 446 }{ 447 {logger.Debug, DebugLevel}, 448 {logger.Info, InfoLevel}, 449 {logger.Warn, WarnLevel}, 450 {logger.Error, ErrorLevel}, 451 {logger.DPanic, DPanicLevel}, 452 } 453 for i, tt := range tests { 454 tt.method("") 455 output := logs.AllUntimed() 456 assert.Equal(t, i+1, len(output), "Unexpected number of logs.") 457 assert.Equal(t, 0, len(output[i].Context), "Unexpected context on first log.") 458 assert.Equal( 459 t, 460 zapcore.Entry{Level: tt.expectedLevel}, 461 output[i].Entry, 462 "Unexpected output from %s-level logger method.", tt.expectedLevel) 463 } 464 }) 465 } 466 467 func TestLoggerLogLevels(t *testing.T) { 468 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 469 levels := []zapcore.Level{ 470 DebugLevel, 471 InfoLevel, 472 WarnLevel, 473 ErrorLevel, 474 DPanicLevel, 475 } 476 for i, level := range levels { 477 logger.Log(level, "") 478 output := logs.AllUntimed() 479 assert.Equal(t, i+1, len(output), "Unexpected number of logs.") 480 assert.Equal(t, 0, len(output[i].Context), "Unexpected context on first log.") 481 assert.Equal( 482 t, 483 zapcore.Entry{Level: level}, 484 output[i].Entry, 485 "Unexpected output from %s-level logger method.", level) 486 } 487 }) 488 } 489 490 func TestLoggerAlwaysPanics(t *testing.T) { 491 // Users can disable writing out panic-level logs, but calls to logger.Panic() 492 // should still call panic(). 493 withLogger(t, FatalLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 494 msg := "Even if output is disabled, logger.Panic should always panic." 495 assert.Panics(t, func() { logger.Panic("foo") }, msg) 496 assert.Panics(t, func() { logger.Log(PanicLevel, "foo") }, msg) 497 assert.Panics(t, func() { 498 if ce := logger.Check(PanicLevel, "foo"); ce != nil { 499 ce.Write() 500 } 501 }, msg) 502 assert.Equal(t, 0, logs.Len(), "Panics shouldn't be written out if PanicLevel is disabled.") 503 }) 504 } 505 506 func TestLoggerAlwaysFatals(t *testing.T) { 507 // Users can disable writing out fatal-level logs, but calls to logger.Fatal() 508 // should still terminate the process. 509 withLogger(t, FatalLevel+1, nil, func(logger *Logger, logs *observer.ObservedLogs) { 510 stub := exit.WithStub(func() { logger.Fatal("") }) 511 assert.True(t, stub.Exited, "Expected calls to logger.Fatal to terminate process.") 512 513 stub = exit.WithStub(func() { logger.Log(FatalLevel, "") }) 514 assert.True(t, stub.Exited, "Expected calls to logger.Fatal to terminate process.") 515 516 stub = exit.WithStub(func() { 517 if ce := logger.Check(FatalLevel, ""); ce != nil { 518 ce.Write() 519 } 520 }) 521 assert.True(t, stub.Exited, "Expected calls to logger.Check(FatalLevel, ...) to terminate process.") 522 523 assert.Equal(t, 0, logs.Len(), "Shouldn't write out logs when fatal-level logging is disabled.") 524 }) 525 } 526 527 func TestLoggerDPanic(t *testing.T) { 528 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 529 assert.NotPanics(t, func() { logger.DPanic("") }) 530 assert.Equal( 531 t, 532 []observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}}, 533 logs.AllUntimed(), 534 "Unexpected log output from DPanic in production mode.", 535 ) 536 }) 537 withLogger(t, DebugLevel, opts(Development()), func(logger *Logger, logs *observer.ObservedLogs) { 538 assert.Panics(t, func() { logger.DPanic("") }) 539 assert.Equal( 540 t, 541 []observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}}, 542 logs.AllUntimed(), 543 "Unexpected log output from DPanic in development mode.", 544 ) 545 }) 546 } 547 548 func TestLoggerNoOpsDisabledLevels(t *testing.T) { 549 withLogger(t, WarnLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 550 logger.Info("silence!") 551 assert.Equal( 552 t, 553 []observer.LoggedEntry{}, 554 logs.AllUntimed(), 555 "Expected logging at a disabled level to produce no output.", 556 ) 557 }) 558 } 559 560 func TestLoggerNames(t *testing.T) { 561 tests := []struct { 562 names []string 563 expected string 564 }{ 565 {nil, ""}, 566 {[]string{""}, ""}, 567 {[]string{"foo"}, "foo"}, 568 {[]string{"foo", ""}, "foo"}, 569 {[]string{"foo", "bar"}, "foo.bar"}, 570 {[]string{"foo.bar", "baz"}, "foo.bar.baz"}, 571 // Garbage in, garbage out. 572 {[]string{"foo.", "bar"}, "foo..bar"}, 573 {[]string{"foo", ".bar"}, "foo..bar"}, 574 {[]string{"foo.", ".bar"}, "foo...bar"}, 575 } 576 577 for _, tt := range tests { 578 withLogger(t, DebugLevel, nil, func(log *Logger, logs *observer.ObservedLogs) { 579 for _, n := range tt.names { 580 log = log.Named(n) 581 } 582 log.Info("") 583 require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.") 584 assert.Equal(t, tt.expected, logs.AllUntimed()[0].LoggerName, "Unexpected logger name from entry.") 585 assert.Equal(t, tt.expected, log.Name(), "Unexpected logger name.") 586 }) 587 withSugar(t, DebugLevel, nil, func(log *SugaredLogger, logs *observer.ObservedLogs) { 588 for _, n := range tt.names { 589 log = log.Named(n) 590 } 591 log.Infow("") 592 require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.") 593 assert.Equal(t, tt.expected, logs.AllUntimed()[0].LoggerName, "Unexpected logger name from entry.") 594 assert.Equal(t, tt.expected, log.base.Name(), "Unexpected logger name.") 595 }) 596 } 597 } 598 599 func TestLoggerWriteFailure(t *testing.T) { 600 errSink := &ztest.Buffer{} 601 logger := New( 602 zapcore.NewCore( 603 zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig), 604 zapcore.Lock(zapcore.AddSync(ztest.FailWriter{})), 605 DebugLevel, 606 ), 607 ErrorOutput(errSink), 608 ) 609 610 logger.Info("foo") 611 // Should log the error. 612 assert.Regexp(t, `write error: failed`, errSink.Stripped(), "Expected to log the error to the error output.") 613 assert.True(t, errSink.Called(), "Expected logging an internal error to call Sync the error sink.") 614 } 615 616 func TestLoggerSync(t *testing.T) { 617 withLogger(t, DebugLevel, nil, func(logger *Logger, _ *observer.ObservedLogs) { 618 assert.NoError(t, logger.Sync(), "Expected syncing a test logger to succeed.") 619 assert.NoError(t, logger.Sugar().Sync(), "Expected syncing a sugared logger to succeed.") 620 }) 621 } 622 623 func TestLoggerSyncFail(t *testing.T) { 624 noSync := &ztest.Buffer{} 625 err := errors.New("fail") 626 noSync.SetError(err) 627 logger := New(zapcore.NewCore( 628 zapcore.NewJSONEncoder(zapcore.EncoderConfig{}), 629 noSync, 630 DebugLevel, 631 )) 632 assert.Equal(t, err, logger.Sync(), "Expected Logger.Sync to propagate errors.") 633 assert.Equal(t, err, logger.Sugar().Sync(), "Expected SugaredLogger.Sync to propagate errors.") 634 } 635 636 func TestLoggerAddCaller(t *testing.T) { 637 tests := []struct { 638 options []Option 639 pat string 640 }{ 641 {opts(), `^undefined$`}, 642 {opts(WithCaller(false)), `^undefined$`}, 643 {opts(AddCaller()), `.+/logger_test.go:[\d]+$`}, 644 {opts(AddCaller(), WithCaller(false)), `^undefined$`}, 645 {opts(WithCaller(true)), `.+/logger_test.go:[\d]+$`}, 646 {opts(WithCaller(true), WithCaller(false)), `^undefined$`}, 647 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), `.+/logger_test.go:[\d]+$`}, 648 {opts(AddCaller(), AddCallerSkip(1)), `.+/common_test.go:[\d]+$`}, 649 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(3)), `.+/src/runtime/.*:[\d]+$`}, 650 } 651 for _, tt := range tests { 652 withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) { 653 // Make sure that sugaring and desugaring resets caller skip properly. 654 logger = logger.Sugar().Desugar() 655 logger.Info("") 656 output := logs.AllUntimed() 657 assert.Equal(t, 1, len(output), "Unexpected number of logs written out.") 658 assert.Regexp( 659 t, 660 tt.pat, 661 output[0].Caller, 662 "Expected to find package name and file name in output.", 663 ) 664 }) 665 } 666 } 667 668 func TestLoggerAddCallerFunction(t *testing.T) { 669 tests := []struct { 670 options []Option 671 loggerFunction string 672 sugaredFunction string 673 }{ 674 { 675 options: opts(), 676 loggerFunction: "", 677 sugaredFunction: "", 678 }, 679 { 680 options: opts(WithCaller(false)), 681 loggerFunction: "", 682 sugaredFunction: "", 683 }, 684 { 685 options: opts(AddCaller()), 686 loggerFunction: "github.com/Laisky/zap.infoLog", 687 sugaredFunction: "github.com/Laisky/zap.infoLogSugared", 688 }, 689 { 690 options: opts(AddCaller(), WithCaller(false)), 691 loggerFunction: "", 692 sugaredFunction: "", 693 }, 694 { 695 options: opts(WithCaller(true)), 696 loggerFunction: "github.com/Laisky/zap.infoLog", 697 sugaredFunction: "github.com/Laisky/zap.infoLogSugared", 698 }, 699 { 700 options: opts(WithCaller(true), WithCaller(false)), 701 loggerFunction: "", 702 sugaredFunction: "", 703 }, 704 { 705 options: opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), 706 loggerFunction: "github.com/Laisky/zap.infoLog", 707 sugaredFunction: "github.com/Laisky/zap.infoLogSugared", 708 }, 709 { 710 options: opts(AddCaller(), AddCallerSkip(2)), 711 loggerFunction: "github.com/Laisky/zap.withLogger", 712 sugaredFunction: "github.com/Laisky/zap.withLogger", 713 }, 714 { 715 options: opts(AddCaller(), AddCallerSkip(2), AddCallerSkip(3)), 716 loggerFunction: "runtime.goexit", 717 sugaredFunction: "runtime.goexit", 718 }, 719 } 720 for _, tt := range tests { 721 withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) { 722 // Make sure that sugaring and desugaring resets caller skip properly. 723 logger = logger.Sugar().Desugar() 724 infoLog(logger, "") 725 infoLogSugared(logger.Sugar(), "") 726 infoLog(logger.Sugar().Desugar(), "") 727 728 entries := logs.AllUntimed() 729 assert.Equal(t, 3, len(entries), "Unexpected number of logs written out.") 730 for _, entry := range []observer.LoggedEntry{entries[0], entries[2]} { 731 assert.Regexp( 732 t, 733 tt.loggerFunction, 734 entry.Caller.Function, 735 "Expected to find function name in output.", 736 ) 737 } 738 assert.Regexp( 739 t, 740 tt.sugaredFunction, 741 entries[1].Caller.Function, 742 "Expected to find function name in output.", 743 ) 744 }) 745 } 746 } 747 748 func TestLoggerAddCallerFail(t *testing.T) { 749 errBuf := &ztest.Buffer{} 750 withLogger(t, DebugLevel, opts(AddCaller(), AddCallerSkip(1e3), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) { 751 log.Info("Failure.") 752 assert.Regexp( 753 t, 754 `Logger.check error: failed to get caller`, 755 errBuf.String(), 756 "Didn't find expected failure message.", 757 ) 758 assert.Equal( 759 t, 760 logs.AllUntimed()[0].Message, 761 "Failure.", 762 "Expected original message to survive failures in runtime.Caller.") 763 assert.Equal( 764 t, 765 logs.AllUntimed()[0].Caller.Function, 766 "", 767 "Expected function name to be empty string.") 768 }) 769 } 770 771 func TestLoggerReplaceCore(t *testing.T) { 772 replace := WrapCore(func(zapcore.Core) zapcore.Core { 773 return zapcore.NewNopCore() 774 }) 775 withLogger(t, DebugLevel, opts(replace), func(logger *Logger, logs *observer.ObservedLogs) { 776 logger.Debug("") 777 logger.Info("") 778 logger.Warn("") 779 assert.Equal(t, 0, logs.Len(), "Expected no-op core to write no logs.") 780 }) 781 } 782 783 func TestLoggerIncreaseLevel(t *testing.T) { 784 withLogger(t, DebugLevel, opts(IncreaseLevel(WarnLevel)), func(logger *Logger, logs *observer.ObservedLogs) { 785 logger.Info("logger.Info") 786 logger.Warn("logger.Warn") 787 logger.Error("logger.Error") 788 require.Equal(t, 2, logs.Len(), "expected only warn + error logs due to IncreaseLevel.") 789 assert.Equal( 790 t, 791 logs.AllUntimed()[0].Message, 792 "logger.Warn", 793 "Expected first logged message to be warn level message", 794 ) 795 }) 796 } 797 798 func TestLoggerHooks(t *testing.T) { 799 hook, seen := makeCountingHook() 800 withLogger(t, DebugLevel, opts(Hooks(hook)), func(logger *Logger, logs *observer.ObservedLogs) { 801 logger.Debug("") 802 logger.Info("") 803 }) 804 assert.Equal(t, int64(2), seen.Load(), "Hook saw an unexpected number of logs.") 805 } 806 807 func TestLoggerHooksWithFields(t *testing.T) { 808 hook, seen := makeCountingHookWithFields() 809 withLogger(t, DebugLevel, opts(HooksWithFields(hook)), func(logger *Logger, logs *observer.ObservedLogs) { 810 logger.Debug("") 811 logger.Info("") 812 }) 813 assert.Equal(t, int64(2), seen.Load(), "Hook saw an unexpected number of logs.") 814 } 815 816 func TestLoggerConcurrent(t *testing.T) { 817 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 818 child := logger.With(String("foo", "bar")) 819 820 wg := &sync.WaitGroup{} 821 runConcurrently(5, 10, wg, func() { 822 logger.Info("", String("foo", "bar")) 823 }) 824 runConcurrently(5, 10, wg, func() { 825 child.Info("") 826 }) 827 828 wg.Wait() 829 830 // Make sure the output doesn't contain interspersed entries. 831 assert.Equal(t, 100, logs.Len(), "Unexpected number of logs written out.") 832 for _, obs := range logs.AllUntimed() { 833 assert.Equal( 834 t, 835 observer.LoggedEntry{ 836 Entry: zapcore.Entry{Level: InfoLevel}, 837 Context: []Field{String("foo", "bar")}, 838 }, 839 obs, 840 "Unexpected log output.", 841 ) 842 } 843 }) 844 } 845 846 func TestLoggerFatalOnNoop(t *testing.T) { 847 exitStub := exit.Stub() 848 defer exitStub.Unstub() 849 core, _ := observer.New(InfoLevel) 850 851 // We don't allow a no-op fatal hook. 852 New(core, WithFatalHook(zapcore.WriteThenNoop)).Fatal("great sadness") 853 assert.True(t, exitStub.Exited, "must exit for WriteThenNoop") 854 assert.Equal(t, 1, exitStub.Code, "must exit with status 1 for WriteThenNoop") 855 } 856 857 func TestLoggerCustomOnPanic(t *testing.T) { 858 tests := []struct { 859 msg string 860 level zapcore.Level 861 opts []Option 862 finished bool 863 want []observer.LoggedEntry 864 recoverValue any 865 }{ 866 { 867 msg: "panic with nil hook", 868 level: PanicLevel, 869 opts: opts(WithPanicHook(nil)), 870 finished: false, 871 want: []observer.LoggedEntry{ 872 { 873 Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"}, 874 Context: []Field{}, 875 }, 876 }, 877 recoverValue: "foobar", 878 }, 879 { 880 msg: "panic with noop hook", 881 level: PanicLevel, 882 opts: opts(WithPanicHook(zapcore.WriteThenNoop)), 883 finished: false, 884 want: []observer.LoggedEntry{ 885 { 886 Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"}, 887 Context: []Field{}, 888 }, 889 }, 890 recoverValue: "foobar", 891 }, 892 { 893 msg: "no panic with goexit hook", 894 level: PanicLevel, 895 opts: opts(WithPanicHook(zapcore.WriteThenGoexit)), 896 finished: false, 897 want: []observer.LoggedEntry{ 898 { 899 Entry: zapcore.Entry{Level: PanicLevel, Message: "foobar"}, 900 Context: []Field{}, 901 }, 902 }, 903 recoverValue: nil, 904 }, 905 { 906 msg: "dpanic no panic in development mode with goexit hook", 907 level: DPanicLevel, 908 opts: opts(WithPanicHook(zapcore.WriteThenGoexit), Development()), 909 finished: false, 910 want: []observer.LoggedEntry{ 911 { 912 Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"}, 913 Context: []Field{}, 914 }, 915 }, 916 recoverValue: nil, 917 }, 918 { 919 msg: "dpanic panic in development mode with noop hook", 920 level: DPanicLevel, 921 opts: opts(WithPanicHook(zapcore.WriteThenNoop), Development()), 922 finished: false, 923 want: []observer.LoggedEntry{ 924 { 925 Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"}, 926 Context: []Field{}, 927 }, 928 }, 929 recoverValue: "foobar", 930 }, 931 { 932 msg: "dpanic no exit in production mode with goexit hook", 933 level: DPanicLevel, 934 opts: opts(WithPanicHook(zapcore.WriteThenPanic)), 935 finished: true, 936 want: []observer.LoggedEntry{ 937 { 938 Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"}, 939 Context: []Field{}, 940 }, 941 }, 942 recoverValue: nil, 943 }, 944 { 945 msg: "dpanic no panic in production mode with panic hook", 946 level: DPanicLevel, 947 opts: opts(WithPanicHook(zapcore.WriteThenPanic)), 948 finished: true, 949 want: []observer.LoggedEntry{ 950 { 951 Entry: zapcore.Entry{Level: DPanicLevel, Message: "foobar"}, 952 Context: []Field{}, 953 }, 954 }, 955 recoverValue: nil, 956 }, 957 } 958 959 for _, tt := range tests { 960 t.Run(tt.msg, func(t *testing.T) { 961 withLogger(t, InfoLevel, tt.opts, func(logger *Logger, logs *observer.ObservedLogs) { 962 var finished bool 963 recovered := make(chan any) 964 go func() { 965 defer func() { 966 recovered <- recover() 967 }() 968 969 logger.Log(tt.level, "foobar") 970 finished = true 971 }() 972 973 assert.Equal(t, tt.recoverValue, <-recovered, "unexpected value from recover()") 974 assert.Equal(t, tt.finished, finished, "expect goroutine finished state doesn't match") 975 assert.Equal(t, tt.want, logs.AllUntimed(), "unexpected logs") 976 }) 977 }) 978 } 979 } 980 981 func TestLoggerCustomOnFatal(t *testing.T) { 982 tests := []struct { 983 msg string 984 onFatal zapcore.CheckWriteAction 985 recoverValue interface{} 986 }{ 987 { 988 msg: "panic", 989 onFatal: zapcore.WriteThenPanic, 990 recoverValue: "fatal", 991 }, 992 { 993 msg: "goexit", 994 onFatal: zapcore.WriteThenGoexit, 995 recoverValue: nil, 996 }, 997 } 998 999 for _, tt := range tests { 1000 t.Run(tt.msg, func(t *testing.T) { 1001 withLogger(t, InfoLevel, opts(OnFatal(tt.onFatal)), func(logger *Logger, logs *observer.ObservedLogs) { 1002 var finished bool 1003 recovered := make(chan interface{}) 1004 go func() { 1005 defer func() { 1006 recovered <- recover() 1007 }() 1008 1009 logger.Fatal("fatal") 1010 finished = true 1011 }() 1012 1013 assert.Equal(t, tt.recoverValue, <-recovered, "unexpected value from recover()") 1014 assert.False(t, finished, "expect goroutine to not finish after Fatal") 1015 1016 assert.Equal(t, []observer.LoggedEntry{{ 1017 Entry: zapcore.Entry{Level: FatalLevel, Message: "fatal"}, 1018 Context: []Field{}, 1019 }}, logs.AllUntimed(), "unexpected logs") 1020 }) 1021 }) 1022 } 1023 } 1024 1025 type customWriteHook struct { 1026 called bool 1027 } 1028 1029 func (h *customWriteHook) OnWrite(_ *zapcore.CheckedEntry, _ []Field) { 1030 h.called = true 1031 } 1032 1033 func TestLoggerWithFatalHook(t *testing.T) { 1034 var h customWriteHook 1035 withLogger(t, InfoLevel, opts(WithFatalHook(&h)), func(logger *Logger, logs *observer.ObservedLogs) { 1036 logger.Fatal("great sadness") 1037 assert.True(t, h.called) 1038 assert.Equal(t, 1, logs.FilterLevelExact(FatalLevel).Len()) 1039 }) 1040 } 1041 1042 func TestNopLogger(t *testing.T) { 1043 logger := NewNop() 1044 1045 t.Run("basic levels", func(t *testing.T) { 1046 logger.Debug("foo", String("k", "v")) 1047 logger.Info("bar", Int("x", 42)) 1048 logger.Warn("baz", Strings("ks", []string{"a", "b"})) 1049 logger.Error("qux", Error(errors.New("great sadness"))) 1050 }) 1051 1052 t.Run("DPanic", func(t *testing.T) { 1053 logger.With(String("component", "whatever")).DPanic("stuff") 1054 }) 1055 1056 t.Run("Panic", func(t *testing.T) { 1057 assert.Panics(t, func() { 1058 logger.Panic("great sadness") 1059 }, "Nop logger should still cause panics.") 1060 }) 1061 } 1062 1063 func TestMust(t *testing.T) { 1064 t.Run("must without an error does not panic", func(t *testing.T) { 1065 assert.NotPanics(t, func() { Must(NewNop(), nil) }, "must paniced with no error") 1066 }) 1067 1068 t.Run("must with an error panics", func(t *testing.T) { 1069 assert.Panics(t, func() { Must(nil, errors.New("an error")) }, "must did not panic with an error") 1070 }) 1071 } 1072 1073 func infoLog(logger *Logger, msg string, fields ...Field) { 1074 logger.Info(msg, fields...) 1075 } 1076 1077 func infoLogSugared(logger *SugaredLogger, args ...interface{}) { 1078 logger.Info(args...) 1079 }