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 21package zap 22 23import ( 24 "errors" 25 "sync" 26 "testing" 27 28 "go.uber.org/zap/internal/exit" 29 "go.uber.org/zap/internal/ztest" 30 "go.uber.org/zap/zapcore" 31 "go.uber.org/zap/zaptest/observer" 32 33 "github.com/stretchr/testify/assert" 34 "github.com/stretchr/testify/require" 35 "go.uber.org/atomic" 36) 37 38func makeCountingHook() (func(zapcore.Entry) error, *atomic.Int64) { 39 count := &atomic.Int64{} 40 h := func(zapcore.Entry) error { 41 count.Inc() 42 return nil 43 } 44 return h, count 45} 46 47func TestLoggerAtomicLevel(t *testing.T) { 48 // Test that the dynamic level applies to all ancestors and descendants. 49 dl := NewAtomicLevel() 50 51 withLogger(t, dl, nil, func(grandparent *Logger, _ *observer.ObservedLogs) { 52 parent := grandparent.With(Int("generation", 1)) 53 child := parent.With(Int("generation", 2)) 54 55 tests := []struct { 56 setLevel zapcore.Level 57 testLevel zapcore.Level 58 enabled bool 59 }{ 60 {DebugLevel, DebugLevel, true}, 61 {InfoLevel, DebugLevel, false}, 62 {WarnLevel, PanicLevel, true}, 63 } 64 65 for _, tt := range tests { 66 dl.SetLevel(tt.setLevel) 67 for _, logger := range []*Logger{grandparent, parent, child} { 68 if tt.enabled { 69 assert.NotNil( 70 t, 71 logger.Check(tt.testLevel, ""), 72 "Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel, 73 ) 74 } else { 75 assert.Nil( 76 t, 77 logger.Check(tt.testLevel, ""), 78 "Expected level %s to be enabled after setting level %s.", tt.testLevel, tt.setLevel, 79 ) 80 } 81 } 82 } 83 }) 84} 85 86func TestLoggerInitialFields(t *testing.T) { 87 fieldOpts := opts(Fields(Int("foo", 42), String("bar", "baz"))) 88 withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { 89 logger.Info("") 90 assert.Equal( 91 t, 92 observer.LoggedEntry{Context: []Field{Int("foo", 42), String("bar", "baz")}}, 93 logs.AllUntimed()[0], 94 "Unexpected output with initial fields set.", 95 ) 96 }) 97} 98 99func TestLoggerWith(t *testing.T) { 100 fieldOpts := opts(Fields(Int("foo", 42))) 101 withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { 102 // Child loggers should have copy-on-write semantics, so two children 103 // shouldn't stomp on each other's fields or affect the parent's fields. 104 logger.With(String("one", "two")).Info("") 105 logger.With(String("three", "four")).Info("") 106 logger.Info("") 107 108 assert.Equal(t, []observer.LoggedEntry{ 109 {Context: []Field{Int("foo", 42), String("one", "two")}}, 110 {Context: []Field{Int("foo", 42), String("three", "four")}}, 111 {Context: []Field{Int("foo", 42)}}, 112 }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") 113 }) 114} 115 116func TestLoggerLogPanic(t *testing.T) { 117 for _, tt := range []struct { 118 do func(*Logger) 119 should bool 120 expected string 121 }{ 122 {func(logger *Logger) { logger.Check(PanicLevel, "bar").Write() }, true, "bar"}, 123 {func(logger *Logger) { logger.Panic("baz") }, true, "baz"}, 124 } { 125 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 126 if tt.should { 127 assert.Panics(t, func() { tt.do(logger) }, "Expected panic") 128 } else { 129 assert.NotPanics(t, func() { tt.do(logger) }, "Expected no panic") 130 } 131 132 output := logs.AllUntimed() 133 assert.Equal(t, 1, len(output), "Unexpected number of logs.") 134 assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.") 135 assert.Equal( 136 t, 137 zapcore.Entry{Message: tt.expected, Level: PanicLevel}, 138 output[0].Entry, 139 "Unexpected output from panic-level Log.", 140 ) 141 }) 142 } 143} 144 145func TestLoggerLogFatal(t *testing.T) { 146 for _, tt := range []struct { 147 do func(*Logger) 148 expected string 149 }{ 150 {func(logger *Logger) { logger.Check(FatalLevel, "bar").Write() }, "bar"}, 151 {func(logger *Logger) { logger.Fatal("baz") }, "baz"}, 152 } { 153 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 154 stub := exit.WithStub(func() { 155 tt.do(logger) 156 }) 157 assert.True(t, stub.Exited, "Expected Fatal logger call to terminate process.") 158 output := logs.AllUntimed() 159 assert.Equal(t, 1, len(output), "Unexpected number of logs.") 160 assert.Equal(t, 0, len(output[0].Context), "Unexpected context on first log.") 161 assert.Equal( 162 t, 163 zapcore.Entry{Message: tt.expected, Level: FatalLevel}, 164 output[0].Entry, 165 "Unexpected output from fatal-level Log.", 166 ) 167 }) 168 } 169} 170 171func TestLoggerLeveledMethods(t *testing.T) { 172 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 173 tests := []struct { 174 method func(string, ...Field) 175 expectedLevel zapcore.Level 176 }{ 177 {logger.Debug, DebugLevel}, 178 {logger.Info, InfoLevel}, 179 {logger.Warn, WarnLevel}, 180 {logger.Error, ErrorLevel}, 181 {logger.DPanic, DPanicLevel}, 182 } 183 for i, tt := range tests { 184 tt.method("") 185 output := logs.AllUntimed() 186 assert.Equal(t, i+1, len(output), "Unexpected number of logs.") 187 assert.Equal(t, 0, len(output[i].Context), "Unexpected context on first log.") 188 assert.Equal( 189 t, 190 zapcore.Entry{Level: tt.expectedLevel}, 191 output[i].Entry, 192 "Unexpected output from %s-level logger method.", tt.expectedLevel) 193 } 194 }) 195} 196 197func TestLoggerAlwaysPanics(t *testing.T) { 198 // Users can disable writing out panic-level logs, but calls to logger.Panic() 199 // should still call panic(). 200 withLogger(t, FatalLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 201 msg := "Even if output is disabled, logger.Panic should always panic." 202 assert.Panics(t, func() { logger.Panic("foo") }, msg) 203 assert.Panics(t, func() { 204 if ce := logger.Check(PanicLevel, "foo"); ce != nil { 205 ce.Write() 206 } 207 }, msg) 208 assert.Equal(t, 0, logs.Len(), "Panics shouldn't be written out if PanicLevel is disabled.") 209 }) 210} 211 212func TestLoggerAlwaysFatals(t *testing.T) { 213 // Users can disable writing out fatal-level logs, but calls to logger.Fatal() 214 // should still terminate the process. 215 withLogger(t, FatalLevel+1, nil, func(logger *Logger, logs *observer.ObservedLogs) { 216 stub := exit.WithStub(func() { logger.Fatal("") }) 217 assert.True(t, stub.Exited, "Expected calls to logger.Fatal to terminate process.") 218 219 stub = exit.WithStub(func() { 220 if ce := logger.Check(FatalLevel, ""); ce != nil { 221 ce.Write() 222 } 223 }) 224 assert.True(t, stub.Exited, "Expected calls to logger.Check(FatalLevel, ...) to terminate process.") 225 226 assert.Equal(t, 0, logs.Len(), "Shouldn't write out logs when fatal-level logging is disabled.") 227 }) 228} 229 230func TestLoggerDPanic(t *testing.T) { 231 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 232 assert.NotPanics(t, func() { logger.DPanic("") }) 233 assert.Equal( 234 t, 235 []observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}}, 236 logs.AllUntimed(), 237 "Unexpected log output from DPanic in production mode.", 238 ) 239 }) 240 withLogger(t, DebugLevel, opts(Development()), func(logger *Logger, logs *observer.ObservedLogs) { 241 assert.Panics(t, func() { logger.DPanic("") }) 242 assert.Equal( 243 t, 244 []observer.LoggedEntry{{Entry: zapcore.Entry{Level: DPanicLevel}, Context: []Field{}}}, 245 logs.AllUntimed(), 246 "Unexpected log output from DPanic in development mode.", 247 ) 248 }) 249} 250 251func TestLoggerNoOpsDisabledLevels(t *testing.T) { 252 withLogger(t, WarnLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 253 logger.Info("silence!") 254 assert.Equal( 255 t, 256 []observer.LoggedEntry{}, 257 logs.AllUntimed(), 258 "Expected logging at a disabled level to produce no output.", 259 ) 260 }) 261} 262 263func TestLoggerNames(t *testing.T) { 264 tests := []struct { 265 names []string 266 expected string 267 }{ 268 {nil, ""}, 269 {[]string{""}, ""}, 270 {[]string{"foo"}, "foo"}, 271 {[]string{"foo", ""}, "foo"}, 272 {[]string{"foo", "bar"}, "foo.bar"}, 273 {[]string{"foo.bar", "baz"}, "foo.bar.baz"}, 274 // Garbage in, garbage out. 275 {[]string{"foo.", "bar"}, "foo..bar"}, 276 {[]string{"foo", ".bar"}, "foo..bar"}, 277 {[]string{"foo.", ".bar"}, "foo...bar"}, 278 } 279 280 for _, tt := range tests { 281 withLogger(t, DebugLevel, nil, func(log *Logger, logs *observer.ObservedLogs) { 282 for _, n := range tt.names { 283 log = log.Named(n) 284 } 285 log.Info("") 286 require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.") 287 assert.Equal(t, tt.expected, logs.AllUntimed()[0].Entry.LoggerName, "Unexpected logger name.") 288 }) 289 withSugar(t, DebugLevel, nil, func(log *SugaredLogger, logs *observer.ObservedLogs) { 290 for _, n := range tt.names { 291 log = log.Named(n) 292 } 293 log.Infow("") 294 require.Equal(t, 1, logs.Len(), "Expected only one log entry to be written.") 295 assert.Equal(t, tt.expected, logs.AllUntimed()[0].Entry.LoggerName, "Unexpected logger name.") 296 }) 297 } 298} 299 300func TestLoggerWriteFailure(t *testing.T) { 301 errSink := &ztest.Buffer{} 302 logger := New( 303 zapcore.NewCore( 304 zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig), 305 zapcore.Lock(zapcore.AddSync(ztest.FailWriter{})), 306 DebugLevel, 307 ), 308 ErrorOutput(errSink), 309 ) 310 311 logger.Info("foo") 312 // Should log the error. 313 assert.Regexp(t, `write error: failed`, errSink.Stripped(), "Expected to log the error to the error output.") 314 assert.True(t, errSink.Called(), "Expected logging an internal error to call Sync the error sink.") 315} 316 317func TestLoggerSync(t *testing.T) { 318 withLogger(t, DebugLevel, nil, func(logger *Logger, _ *observer.ObservedLogs) { 319 assert.NoError(t, logger.Sync(), "Expected syncing a test logger to succeed.") 320 assert.NoError(t, logger.Sugar().Sync(), "Expected syncing a sugared logger to succeed.") 321 }) 322} 323 324func TestLoggerSyncFail(t *testing.T) { 325 noSync := &ztest.Buffer{} 326 err := errors.New("fail") 327 noSync.SetError(err) 328 logger := New(zapcore.NewCore( 329 zapcore.NewJSONEncoder(zapcore.EncoderConfig{}), 330 noSync, 331 DebugLevel, 332 )) 333 assert.Equal(t, err, logger.Sync(), "Expected Logger.Sync to propagate errors.") 334 assert.Equal(t, err, logger.Sugar().Sync(), "Expected SugaredLogger.Sync to propagate errors.") 335} 336 337func TestLoggerAddCaller(t *testing.T) { 338 tests := []struct { 339 options []Option 340 pat string 341 }{ 342 {opts(AddCaller()), `.+/logger_test.go:[\d]+$`}, 343 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), `.+/zap/logger_test.go:[\d]+$`}, 344 {opts(AddCaller(), AddCallerSkip(1)), `.+/zap/common_test.go:[\d]+$`}, 345 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(3)), `.+/src/runtime/.*:[\d]+$`}, 346 } 347 for _, tt := range tests { 348 withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) { 349 // Make sure that sugaring and desugaring resets caller skip properly. 350 logger = logger.Sugar().Desugar() 351 logger.Info("") 352 output := logs.AllUntimed() 353 assert.Equal(t, 1, len(output), "Unexpected number of logs written out.") 354 assert.Regexp( 355 t, 356 tt.pat, 357 output[0].Entry.Caller, 358 "Expected to find package name and file name in output.", 359 ) 360 }) 361 } 362} 363 364func TestLoggerAddCallerFail(t *testing.T) { 365 errBuf := &ztest.Buffer{} 366 withLogger(t, DebugLevel, opts(AddCaller(), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) { 367 log.callerSkip = 1e3 368 log.Info("Failure.") 369 assert.Regexp( 370 t, 371 `Logger.check error: failed to get caller`, 372 errBuf.String(), 373 "Didn't find expected failure message.", 374 ) 375 assert.Equal( 376 t, 377 logs.AllUntimed()[0].Entry.Message, 378 "Failure.", 379 "Expected original message to survive failures in runtime.Caller.") 380 }) 381} 382 383func TestLoggerReplaceCore(t *testing.T) { 384 replace := WrapCore(func(zapcore.Core) zapcore.Core { 385 return zapcore.NewNopCore() 386 }) 387 withLogger(t, DebugLevel, opts(replace), func(logger *Logger, logs *observer.ObservedLogs) { 388 logger.Debug("") 389 logger.Info("") 390 logger.Warn("") 391 assert.Equal(t, 0, logs.Len(), "Expected no-op core to write no logs.") 392 }) 393} 394 395func TestLoggerHooks(t *testing.T) { 396 hook, seen := makeCountingHook() 397 withLogger(t, DebugLevel, opts(Hooks(hook)), func(logger *Logger, logs *observer.ObservedLogs) { 398 logger.Debug("") 399 logger.Info("") 400 }) 401 assert.Equal(t, int64(2), seen.Load(), "Hook saw an unexpected number of logs.") 402} 403 404func TestLoggerConcurrent(t *testing.T) { 405 withLogger(t, DebugLevel, nil, func(logger *Logger, logs *observer.ObservedLogs) { 406 child := logger.With(String("foo", "bar")) 407 408 wg := &sync.WaitGroup{} 409 runConcurrently(5, 10, wg, func() { 410 logger.Info("", String("foo", "bar")) 411 }) 412 runConcurrently(5, 10, wg, func() { 413 child.Info("") 414 }) 415 416 wg.Wait() 417 418 // Make sure the output doesn't contain interspersed entries. 419 assert.Equal(t, 100, logs.Len(), "Unexpected number of logs written out.") 420 for _, obs := range logs.AllUntimed() { 421 assert.Equal( 422 t, 423 observer.LoggedEntry{ 424 Entry: zapcore.Entry{Level: InfoLevel}, 425 Context: []Field{String("foo", "bar")}, 426 }, 427 obs, 428 "Unexpected log output.", 429 ) 430 } 431 }) 432} 433