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  }