Source file src/go.uber.org/zap/logger_test.go

Documentation: go.uber.org/zap

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

View as plain text