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 "testing" 25 26 "go.uber.org/zap/internal/exit" 27 "go.uber.org/zap/internal/ztest" 28 "go.uber.org/zap/zapcore" 29 "go.uber.org/zap/zaptest/observer" 30 31 "github.com/stretchr/testify/assert" 32 "github.com/stretchr/testify/require" 33) 34 35func TestSugarWith(t *testing.T) { 36 // Convenience functions to create expected error logs. 37 ignored := func(msg interface{}) observer.LoggedEntry { 38 return observer.LoggedEntry{ 39 Entry: zapcore.Entry{Level: DPanicLevel, Message: _oddNumberErrMsg}, 40 Context: []Field{Any("ignored", msg)}, 41 } 42 } 43 nonString := func(pairs ...invalidPair) observer.LoggedEntry { 44 return observer.LoggedEntry{ 45 Entry: zapcore.Entry{Level: DPanicLevel, Message: _nonStringKeyErrMsg}, 46 Context: []Field{Array("invalid", invalidPairs(pairs))}, 47 } 48 } 49 50 tests := []struct { 51 desc string 52 args []interface{} 53 expected []Field 54 errLogs []observer.LoggedEntry 55 }{ 56 { 57 desc: "nil args", 58 args: nil, 59 expected: []Field{}, 60 errLogs: nil, 61 }, 62 { 63 desc: "empty slice of args", 64 args: []interface{}{}, 65 expected: []Field{}, 66 errLogs: nil, 67 }, 68 { 69 desc: "just a dangling key", 70 args: []interface{}{"should ignore"}, 71 expected: []Field{}, 72 errLogs: []observer.LoggedEntry{ignored("should ignore")}, 73 }, 74 { 75 desc: "well-formed key-value pairs", 76 args: []interface{}{"foo", 42, "true", "bar"}, 77 expected: []Field{Int("foo", 42), String("true", "bar")}, 78 errLogs: nil, 79 }, 80 { 81 desc: "just a structured field", 82 args: []interface{}{Int("foo", 42)}, 83 expected: []Field{Int("foo", 42)}, 84 errLogs: nil, 85 }, 86 { 87 desc: "structured field and a dangling key", 88 args: []interface{}{Int("foo", 42), "dangling"}, 89 expected: []Field{Int("foo", 42)}, 90 errLogs: []observer.LoggedEntry{ignored("dangling")}, 91 }, 92 { 93 desc: "structured field and a dangling non-string key", 94 args: []interface{}{Int("foo", 42), 13}, 95 expected: []Field{Int("foo", 42)}, 96 errLogs: []observer.LoggedEntry{ignored(13)}, 97 }, 98 { 99 desc: "key-value pair and a dangling key", 100 args: []interface{}{"foo", 42, "dangling"}, 101 expected: []Field{Int("foo", 42)}, 102 errLogs: []observer.LoggedEntry{ignored("dangling")}, 103 }, 104 { 105 desc: "pairs, a structured field, and a dangling key", 106 args: []interface{}{"first", "field", Int("foo", 42), "baz", "quux", "dangling"}, 107 expected: []Field{String("first", "field"), Int("foo", 42), String("baz", "quux")}, 108 errLogs: []observer.LoggedEntry{ignored("dangling")}, 109 }, 110 { 111 desc: "one non-string key", 112 args: []interface{}{"foo", 42, true, "bar"}, 113 expected: []Field{Int("foo", 42)}, 114 errLogs: []observer.LoggedEntry{nonString(invalidPair{2, true, "bar"})}, 115 }, 116 { 117 desc: "pairs, structured fields, non-string keys, and a dangling key", 118 args: []interface{}{"foo", 42, true, "bar", Int("structure", 11), 42, "reversed", "baz", "quux", "dangling"}, 119 expected: []Field{Int("foo", 42), Int("structure", 11), String("baz", "quux")}, 120 errLogs: []observer.LoggedEntry{ 121 ignored("dangling"), 122 nonString(invalidPair{2, true, "bar"}, invalidPair{5, 42, "reversed"}), 123 }, 124 }, 125 } 126 127 for _, tt := range tests { 128 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 129 logger.With(tt.args...).Info("") 130 output := logs.AllUntimed() 131 if len(tt.errLogs) > 0 { 132 for i := range tt.errLogs { 133 assert.Equal(t, tt.errLogs[i], output[i], "Unexpected error log at position %d for scenario %s.", i, tt.desc) 134 } 135 } 136 assert.Equal(t, len(tt.errLogs)+1, len(output), "Expected only one non-error message to be logged in scenario %s.", tt.desc) 137 assert.Equal(t, tt.expected, output[len(tt.errLogs)].Context, "Unexpected message context in scenario %s.", tt.desc) 138 }) 139 } 140} 141 142func TestSugarFieldsInvalidPairs(t *testing.T) { 143 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 144 logger.With(42, "foo", []string{"bar"}, "baz").Info("") 145 output := logs.AllUntimed() 146 147 // Double-check that the actual message was logged. 148 require.Equal(t, 2, len(output), "Unexpected number of entries logged.") 149 require.Equal(t, observer.LoggedEntry{Context: []Field{}}, output[1], "Unexpected non-error log entry.") 150 151 // Assert that the error message's structured fields serialize properly. 152 require.Equal(t, 1, len(output[0].Context), "Expected one field in error entry context.") 153 enc := zapcore.NewMapObjectEncoder() 154 output[0].Context[0].AddTo(enc) 155 assert.Equal(t, []interface{}{ 156 map[string]interface{}{"position": int64(0), "key": int64(42), "value": "foo"}, 157 map[string]interface{}{"position": int64(2), "key": []interface{}{"bar"}, "value": "baz"}, 158 }, enc.Fields["invalid"], "Unexpected output when logging invalid key-value pairs.") 159 }) 160} 161 162type stringerF func() string 163 164func (f stringerF) String() string { return f() } 165 166func TestSugarStructuredLogging(t *testing.T) { 167 tests := []struct { 168 msg string 169 expectMsg string 170 }{ 171 {"foo", "foo"}, 172 {"", ""}, 173 } 174 175 // Common to all test cases. 176 context := []interface{}{"foo", "bar"} 177 extra := []interface{}{"baz", false} 178 expectedFields := []Field{String("foo", "bar"), Bool("baz", false)} 179 180 for _, tt := range tests { 181 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 182 logger.With(context...).Debugw(tt.msg, extra...) 183 logger.With(context...).Infow(tt.msg, extra...) 184 logger.With(context...).Warnw(tt.msg, extra...) 185 logger.With(context...).Errorw(tt.msg, extra...) 186 logger.With(context...).DPanicw(tt.msg, extra...) 187 188 expected := make([]observer.LoggedEntry, 5) 189 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 190 expected[i] = observer.LoggedEntry{ 191 Entry: zapcore.Entry{Message: tt.expectMsg, Level: lvl}, 192 Context: expectedFields, 193 } 194 } 195 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 196 }) 197 } 198} 199 200func TestSugarConcatenatingLogging(t *testing.T) { 201 tests := []struct { 202 args []interface{} 203 expect string 204 }{ 205 {[]interface{}{nil}, "<nil>"}, 206 } 207 208 // Common to all test cases. 209 context := []interface{}{"foo", "bar"} 210 expectedFields := []Field{String("foo", "bar")} 211 212 for _, tt := range tests { 213 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 214 logger.With(context...).Debug(tt.args...) 215 logger.With(context...).Info(tt.args...) 216 logger.With(context...).Warn(tt.args...) 217 logger.With(context...).Error(tt.args...) 218 logger.With(context...).DPanic(tt.args...) 219 220 expected := make([]observer.LoggedEntry, 5) 221 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 222 expected[i] = observer.LoggedEntry{ 223 Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, 224 Context: expectedFields, 225 } 226 } 227 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 228 }) 229 } 230} 231 232func TestSugarTemplatedLogging(t *testing.T) { 233 tests := []struct { 234 format string 235 args []interface{} 236 expect string 237 }{ 238 {"", nil, ""}, 239 {"foo", nil, "foo"}, 240 // If the user fails to pass a template, degrade to fmt.Sprint. 241 {"", []interface{}{"foo"}, "foo"}, 242 } 243 244 // Common to all test cases. 245 context := []interface{}{"foo", "bar"} 246 expectedFields := []Field{String("foo", "bar")} 247 248 for _, tt := range tests { 249 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 250 logger.With(context...).Debugf(tt.format, tt.args...) 251 logger.With(context...).Infof(tt.format, tt.args...) 252 logger.With(context...).Warnf(tt.format, tt.args...) 253 logger.With(context...).Errorf(tt.format, tt.args...) 254 logger.With(context...).DPanicf(tt.format, tt.args...) 255 256 expected := make([]observer.LoggedEntry, 5) 257 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 258 expected[i] = observer.LoggedEntry{ 259 Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, 260 Context: expectedFields, 261 } 262 } 263 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 264 }) 265 } 266} 267 268func TestSugarPanicLogging(t *testing.T) { 269 tests := []struct { 270 loggerLevel zapcore.Level 271 f func(*SugaredLogger) 272 expectedMsg string 273 }{ 274 {FatalLevel, func(s *SugaredLogger) { s.Panic("foo") }, ""}, 275 {PanicLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, 276 {DebugLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, 277 {FatalLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, ""}, 278 {PanicLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"}, 279 {DebugLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"}, 280 {FatalLevel, func(s *SugaredLogger) { s.Panicw("foo") }, ""}, 281 {PanicLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"}, 282 {DebugLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"}, 283 } 284 285 for _, tt := range tests { 286 withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { 287 assert.Panics(t, func() { tt.f(sugar) }, "Expected panic-level logger calls to panic.") 288 if tt.expectedMsg != "" { 289 assert.Equal(t, []observer.LoggedEntry{{ 290 Context: []Field{}, 291 Entry: zapcore.Entry{Message: tt.expectedMsg, Level: PanicLevel}, 292 }}, logs.AllUntimed(), "Unexpected log output.") 293 } else { 294 assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") 295 } 296 }) 297 } 298} 299 300func TestSugarFatalLogging(t *testing.T) { 301 tests := []struct { 302 loggerLevel zapcore.Level 303 f func(*SugaredLogger) 304 expectedMsg string 305 }{ 306 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatal("foo") }, ""}, 307 {FatalLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, 308 {DebugLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, 309 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, ""}, 310 {FatalLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"}, 311 {DebugLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"}, 312 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatalw("foo") }, ""}, 313 {FatalLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"}, 314 {DebugLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"}, 315 } 316 317 for _, tt := range tests { 318 withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { 319 stub := exit.WithStub(func() { tt.f(sugar) }) 320 assert.True(t, stub.Exited, "Expected all calls to fatal logger methods to exit process.") 321 if tt.expectedMsg != "" { 322 assert.Equal(t, []observer.LoggedEntry{{ 323 Context: []Field{}, 324 Entry: zapcore.Entry{Message: tt.expectedMsg, Level: FatalLevel}, 325 }}, logs.AllUntimed(), "Unexpected log output.") 326 } else { 327 assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") 328 } 329 }) 330 } 331} 332 333func TestSugarAddCaller(t *testing.T) { 334 tests := []struct { 335 options []Option 336 pat string 337 }{ 338 {opts(AddCaller()), `.+/sugar_test.go:[\d]+$`}, 339 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), `.+/zap/sugar_test.go:[\d]+$`}, 340 {opts(AddCaller(), AddCallerSkip(1)), `.+/zap/common_test.go:[\d]+$`}, 341 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(5)), `.+/src/runtime/.*:[\d]+$`}, 342 } 343 for _, tt := range tests { 344 withSugar(t, DebugLevel, tt.options, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 345 logger.Info("") 346 output := logs.AllUntimed() 347 assert.Equal(t, 1, len(output), "Unexpected number of logs written out.") 348 assert.Regexp( 349 t, 350 tt.pat, 351 output[0].Entry.Caller, 352 "Expected to find package name and file name in output.", 353 ) 354 }) 355 } 356} 357 358func TestSugarAddCallerFail(t *testing.T) { 359 errBuf := &ztest.Buffer{} 360 withSugar(t, DebugLevel, opts(AddCaller(), AddCallerSkip(1e3), ErrorOutput(errBuf)), func(log *SugaredLogger, logs *observer.ObservedLogs) { 361 log.Info("Failure.") 362 assert.Regexp( 363 t, 364 `Logger.check error: failed to get caller`, 365 errBuf.String(), 366 "Didn't find expected failure message.", 367 ) 368 assert.Equal( 369 t, 370 logs.AllUntimed()[0].Entry.Message, 371 "Failure.", 372 "Expected original message to survive failures in runtime.Caller.") 373 }) 374} 375