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 162func TestSugarStructuredLogging(t *testing.T) { 163 tests := []struct { 164 msg string 165 expectMsg string 166 }{ 167 {"foo", "foo"}, 168 {"", ""}, 169 } 170 171 // Common to all test cases. 172 context := []interface{}{"foo", "bar"} 173 extra := []interface{}{"baz", false} 174 expectedFields := []Field{String("foo", "bar"), Bool("baz", false)} 175 176 for _, tt := range tests { 177 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 178 logger.With(context...).Debugw(tt.msg, extra...) 179 logger.With(context...).Infow(tt.msg, extra...) 180 logger.With(context...).Warnw(tt.msg, extra...) 181 logger.With(context...).Errorw(tt.msg, extra...) 182 logger.With(context...).DPanicw(tt.msg, extra...) 183 184 expected := make([]observer.LoggedEntry, 5) 185 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 186 expected[i] = observer.LoggedEntry{ 187 Entry: zapcore.Entry{Message: tt.expectMsg, Level: lvl}, 188 Context: expectedFields, 189 } 190 } 191 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 192 }) 193 } 194} 195 196func TestSugarConcatenatingLogging(t *testing.T) { 197 tests := []struct { 198 args []interface{} 199 expect string 200 }{ 201 {[]interface{}{nil}, "<nil>"}, 202 } 203 204 // Common to all test cases. 205 context := []interface{}{"foo", "bar"} 206 expectedFields := []Field{String("foo", "bar")} 207 208 for _, tt := range tests { 209 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 210 logger.With(context...).Debug(tt.args...) 211 logger.With(context...).Info(tt.args...) 212 logger.With(context...).Warn(tt.args...) 213 logger.With(context...).Error(tt.args...) 214 logger.With(context...).DPanic(tt.args...) 215 216 expected := make([]observer.LoggedEntry, 5) 217 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 218 expected[i] = observer.LoggedEntry{ 219 Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, 220 Context: expectedFields, 221 } 222 } 223 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 224 }) 225 } 226} 227 228func TestSugarTemplatedLogging(t *testing.T) { 229 tests := []struct { 230 format string 231 args []interface{} 232 expect string 233 }{ 234 {"", nil, ""}, 235 {"foo", nil, "foo"}, 236 // If the user fails to pass a template, degrade to fmt.Sprint. 237 {"", []interface{}{"foo"}, "foo"}, 238 } 239 240 // Common to all test cases. 241 context := []interface{}{"foo", "bar"} 242 expectedFields := []Field{String("foo", "bar")} 243 244 for _, tt := range tests { 245 withSugar(t, DebugLevel, nil, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 246 logger.With(context...).Debugf(tt.format, tt.args...) 247 logger.With(context...).Infof(tt.format, tt.args...) 248 logger.With(context...).Warnf(tt.format, tt.args...) 249 logger.With(context...).Errorf(tt.format, tt.args...) 250 logger.With(context...).DPanicf(tt.format, tt.args...) 251 252 expected := make([]observer.LoggedEntry, 5) 253 for i, lvl := range []zapcore.Level{DebugLevel, InfoLevel, WarnLevel, ErrorLevel, DPanicLevel} { 254 expected[i] = observer.LoggedEntry{ 255 Entry: zapcore.Entry{Message: tt.expect, Level: lvl}, 256 Context: expectedFields, 257 } 258 } 259 assert.Equal(t, expected, logs.AllUntimed(), "Unexpected log output.") 260 }) 261 } 262} 263 264func TestSugarPanicLogging(t *testing.T) { 265 tests := []struct { 266 loggerLevel zapcore.Level 267 f func(*SugaredLogger) 268 expectedMsg string 269 }{ 270 {FatalLevel, func(s *SugaredLogger) { s.Panic("foo") }, ""}, 271 {PanicLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, 272 {DebugLevel, func(s *SugaredLogger) { s.Panic("foo") }, "foo"}, 273 {FatalLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, ""}, 274 {PanicLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"}, 275 {DebugLevel, func(s *SugaredLogger) { s.Panicf("%s", "foo") }, "foo"}, 276 {FatalLevel, func(s *SugaredLogger) { s.Panicw("foo") }, ""}, 277 {PanicLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"}, 278 {DebugLevel, func(s *SugaredLogger) { s.Panicw("foo") }, "foo"}, 279 } 280 281 for _, tt := range tests { 282 withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { 283 assert.Panics(t, func() { tt.f(sugar) }, "Expected panic-level logger calls to panic.") 284 if tt.expectedMsg != "" { 285 assert.Equal(t, []observer.LoggedEntry{{ 286 Context: []Field{}, 287 Entry: zapcore.Entry{Message: tt.expectedMsg, Level: PanicLevel}, 288 }}, logs.AllUntimed(), "Unexpected log output.") 289 } else { 290 assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") 291 } 292 }) 293 } 294} 295 296func TestSugarFatalLogging(t *testing.T) { 297 tests := []struct { 298 loggerLevel zapcore.Level 299 f func(*SugaredLogger) 300 expectedMsg string 301 }{ 302 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatal("foo") }, ""}, 303 {FatalLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, 304 {DebugLevel, func(s *SugaredLogger) { s.Fatal("foo") }, "foo"}, 305 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, ""}, 306 {FatalLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"}, 307 {DebugLevel, func(s *SugaredLogger) { s.Fatalf("%s", "foo") }, "foo"}, 308 {FatalLevel + 1, func(s *SugaredLogger) { s.Fatalw("foo") }, ""}, 309 {FatalLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"}, 310 {DebugLevel, func(s *SugaredLogger) { s.Fatalw("foo") }, "foo"}, 311 } 312 313 for _, tt := range tests { 314 withSugar(t, tt.loggerLevel, nil, func(sugar *SugaredLogger, logs *observer.ObservedLogs) { 315 stub := exit.WithStub(func() { tt.f(sugar) }) 316 assert.True(t, stub.Exited, "Expected all calls to fatal logger methods to exit process.") 317 if tt.expectedMsg != "" { 318 assert.Equal(t, []observer.LoggedEntry{{ 319 Context: []Field{}, 320 Entry: zapcore.Entry{Message: tt.expectedMsg, Level: FatalLevel}, 321 }}, logs.AllUntimed(), "Unexpected log output.") 322 } else { 323 assert.Equal(t, 0, logs.Len(), "Didn't expect any log output.") 324 } 325 }) 326 } 327} 328 329func TestSugarAddCaller(t *testing.T) { 330 tests := []struct { 331 options []Option 332 pat string 333 }{ 334 {opts(AddCaller()), `.+/sugar_test.go:[\d]+$`}, 335 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)), `.+/zap/sugar_test.go:[\d]+$`}, 336 {opts(AddCaller(), AddCallerSkip(1)), `.+/zap/common_test.go:[\d]+$`}, 337 {opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(5)), `.+/src/runtime/.*:[\d]+$`}, 338 } 339 for _, tt := range tests { 340 withSugar(t, DebugLevel, tt.options, func(logger *SugaredLogger, logs *observer.ObservedLogs) { 341 logger.Info("") 342 output := logs.AllUntimed() 343 assert.Equal(t, 1, len(output), "Unexpected number of logs written out.") 344 assert.Regexp( 345 t, 346 tt.pat, 347 output[0].Entry.Caller, 348 "Expected to find package name and file name in output.", 349 ) 350 }) 351 } 352} 353 354func TestSugarAddCallerFail(t *testing.T) { 355 errBuf := &ztest.Buffer{} 356 withSugar(t, DebugLevel, opts(AddCaller(), AddCallerSkip(1e3), ErrorOutput(errBuf)), func(log *SugaredLogger, logs *observer.ObservedLogs) { 357 log.Info("Failure.") 358 assert.Regexp( 359 t, 360 `Logger.check error: failed to get caller`, 361 errBuf.String(), 362 "Didn't find expected failure message.", 363 ) 364 assert.Equal( 365 t, 366 logs.AllUntimed()[0].Entry.Message, 367 "Failure.", 368 "Expected original message to survive failures in runtime.Caller.") 369 }) 370} 371