CHANGELOG.md

@@ -1,16 +1,37 @@
 # Changelog
 
+## 1.16.0 (1 Sep 2020)
+
+Bugfixes:
+* [#828][]: Fix missing newline in IncreaseLevel error messages.
+* [#835][]: Fix panic in JSON encoder when encoding times or durations
+  without specifying a time or duration encoder.
+* [#843][]: Honor CallerSkip when taking stack traces.
+* [#862][]: Fix the default file permissions to use `0666` and rely on the umask instead.
+* [#854][]: Encode `<nil>` for nil `Stringer` instead of a panic error log.
+
+Enhancements:
+* [#629][]: Added `zapcore.TimeEncoderOfLayout` to easily create time encoders
+  for custom layouts.
+* [#697][]: Added support for a configurable delimiter in the console encoder.
+* [#852][]: Optimize console encoder by pooling the underlying JSON encoder.
+* [#844][]: Add ability to include the calling function as part of logs.
+* [#843][]: Add `StackSkip` for including truncated stacks as a field.
+* [#861][]: Add options to customize Fatal behaviour for better testability.
+
+Thanks to @SteelPhase, @tmshn, @lixingwang, @wyxloading, @moul, @segevfiner, @andy-retailnext and @jcorbin for their contributions to this release.
+
 ## 1.15.0 (23 Apr 2020)
 
 Bugfixes:
 * [#804][]: Fix handling of `Time` values out of `UnixNano` range.
-* [#812][]: Fix `IncreaseLevel` being reset after a call to `With`.  
+* [#812][]: Fix `IncreaseLevel` being reset after a call to `With`.
 
 Enhancements:
 * [#806][]: Add `WithCaller` option to supersede the `AddCaller` option. This
   allows disabling annotation of log entries with caller information if
   previously enabled with `AddCaller`.
-* [#813][]: Deprecate `NewSampler` constructor in favor of 
+* [#813][]: Deprecate `NewSampler` constructor in favor of
   `NewSamplerWithOptions` which supports a `SamplerHook` option. This option
    adds support for monitoring sampling decisions through a hook.
 
@@ -399,3 +420,13 @@ upgrade to the upcoming stable release.
 [#812]: https://github.com/uber-go/zap/pull/812
 [#806]: https://github.com/uber-go/zap/pull/806
 [#813]: https://github.com/uber-go/zap/pull/813
+[#629]: https://github.com/uber-go/zap/pull/629
+[#697]: https://github.com/uber-go/zap/pull/697
+[#828]: https://github.com/uber-go/zap/pull/828
+[#835]: https://github.com/uber-go/zap/pull/835
+[#843]: https://github.com/uber-go/zap/pull/843
+[#844]: https://github.com/uber-go/zap/pull/844
+[#852]: https://github.com/uber-go/zap/pull/852
+[#854]: https://github.com/uber-go/zap/pull/854
+[#861]: https://github.com/uber-go/zap/pull/861
+[#862]: https://github.com/uber-go/zap/pull/862

FAQ.md

@@ -149,6 +149,7 @@ We're aware of the following extensions, but haven't used them ourselves:
 | `github.com/tchap/zapext` | Sentry, syslog |
 | `github.com/fgrosse/zaptest` | Ginkgo |
 | `github.com/blendle/zapdriver` | Stackdriver |
+| `github.com/moul/zapgorm` | Gorm |
 
 [go-proverbs]: https://go-proverbs.github.io/
 [import-path]: https://golang.org/cmd/go/#hdr-Remote_import_paths

config.go

@@ -101,6 +101,7 @@ func NewProductionEncoderConfig() zapcore.EncoderConfig {
 		LevelKey:       "level",
 		NameKey:        "logger",
 		CallerKey:      "caller",
+		FunctionKey:    zapcore.OmitKey,
 		MessageKey:     "msg",
 		StacktraceKey:  "stacktrace",
 		LineEnding:     zapcore.DefaultLineEnding,
@@ -140,6 +141,7 @@ func NewDevelopmentEncoderConfig() zapcore.EncoderConfig {
 		LevelKey:       "L",
 		NameKey:        "N",
 		CallerKey:      "C",
+		FunctionKey:    zapcore.OmitKey,
 		MessageKey:     "M",
 		StacktraceKey:  "S",
 		LineEnding:     zapcore.DefaultLineEnding,

config_test.go

@@ -52,7 +52,7 @@ func TestConfig(t *testing.T) {
 			expectRe: "DEBUG\tzap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" +
 				"INFO\tzap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" +
 				"WARN\tzap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" +
-				`testing.\w+`,
+				`go.uber.org/zap.TestConfig.\w+`,
 		},
 	}
 

field.go

@@ -364,11 +364,17 @@ func Timep(key string, val *time.Time) Field {
 // expensive (relatively speaking); this function both makes an allocation and
 // takes about two microseconds.
 func Stack(key string) Field {
+	return StackSkip(key, 1) // skip Stack
+}
+
+// StackSkip constructs a field similarly to Stack, but also skips the given
+// number of frames from the top of the stacktrace.
+func StackSkip(key string, skip int) Field {
 	// Returning the stacktrace as a string costs an allocation, but saves us
 	// from expanding the zapcore.Field union struct to include a byte slice. Since
 	// taking a stacktrace is already so expensive (~10us), the extra allocation
 	// is okay.
-	return String(key, takeStacktrace())
+	return String(key, takeStacktrace(skip+1)) // skip StackSkip
 }
 
 // Duration constructs a field with the given key and value. The encoder

field_test.go

@@ -23,6 +23,7 @@ package zap
 import (
 	"math"
 	"net"
+	"regexp"
 	"sync"
 	"testing"
 	"time"
@@ -259,6 +260,24 @@ func TestStackField(t *testing.T) {
 	f := Stack("stacktrace")
 	assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.")
 	assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.")
-	assert.Equal(t, takeStacktrace(), f.String, "Unexpected stack trace")
+	r := regexp.MustCompile(`field_test.go:(\d+)`)
+	assert.Equal(t, r.ReplaceAllString(takeStacktrace(0), "field_test.go"), r.ReplaceAllString(f.String, "field_test.go"), "Unexpected stack trace")
+	assertCanBeReused(t, f)
+}
+
+func TestStackSkipField(t *testing.T) {
+	f := StackSkip("stacktrace", 0)
+	assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.")
+	assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.")
+	r := regexp.MustCompile(`field_test.go:(\d+)`)
+	assert.Equal(t, r.ReplaceAllString(takeStacktrace(0), "field_test.go"), r.ReplaceAllString(f.String, "field_test.go"), f.String, "Unexpected stack trace")
+	assertCanBeReused(t, f)
+}
+
+func TestStackSkipFieldWithSkip(t *testing.T) {
+	f := StackSkip("stacktrace", 1)
+	assert.Equal(t, "stacktrace", f.Key, "Unexpected field key.")
+	assert.Equal(t, zapcore.StringType, f.Type, "Unexpected field type.")
+	assert.Equal(t, takeStacktrace(1), f.String, "Unexpected stack trace")
 	assertCanBeReused(t, f)
 }

go.mod

@@ -8,5 +8,6 @@ require (
 	go.uber.org/atomic v1.6.0
 	go.uber.org/multierr v1.5.0
 	golang.org/x/lint v0.0.0-20190930215403-16217165b5de
+	gopkg.in/yaml.v2 v2.2.2
 	honnef.co/go/tools v0.0.1-2019.2.3
 )

increase_level_test.go

@@ -58,7 +58,7 @@ func TestIncreaseLevelTryDecrease(t *testing.T) {
 			newLoggedEntry(ErrorLevel, "increase level error log"),
 		}, logs.AllUntimed(), "unexpected logs")
 		assert.Equal(t,
-			`failed to IncreaseLevel: invalid increase level, as level "info" is allowed by increased level, but not by existing core`,
+			"failed to IncreaseLevel: invalid increase level, as level \"info\" is allowed by increased level, but not by existing core\n",
 			errorOut.String(),
 			"unexpected error output",
 		)

logger.go

@@ -49,6 +49,7 @@ type Logger struct {
 	addStack  zapcore.LevelEnabler
 
 	callerSkip int
+	onFatal    zapcore.CheckWriteAction // default is WriteThenFatal
 }
 
 // New constructs a new Logger from the provided zapcore.Core and Options. If
@@ -280,7 +281,13 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
 	case zapcore.PanicLevel:
 		ce = ce.Should(ent, zapcore.WriteThenPanic)
 	case zapcore.FatalLevel:
-		ce = ce.Should(ent, zapcore.WriteThenFatal)
+		onFatal := log.onFatal
+		// Noop is the default value for CheckWriteAction, and it leads to
+		// continued execution after a Fatal which is unexpected.
+		if onFatal == zapcore.WriteThenNoop {
+			onFatal = zapcore.WriteThenFatal
+		}
+		ce = ce.Should(ent, onFatal)
 	case zapcore.DPanicLevel:
 		if log.development {
 			ce = ce.Should(ent, zapcore.WriteThenPanic)
@@ -297,15 +304,41 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
 	// Thread the error output through to the CheckedEntry.
 	ce.ErrorOutput = log.errorOutput
 	if log.addCaller {
-		ce.Entry.Caller = zapcore.NewEntryCaller(runtime.Caller(log.callerSkip + callerSkipOffset))
-		if !ce.Entry.Caller.Defined {
+		frame, defined := getCallerFrame(log.callerSkip + callerSkipOffset)
+		if !defined {
 			fmt.Fprintf(log.errorOutput, "%v Logger.check error: failed to get caller\n", time.Now().UTC())
 			log.errorOutput.Sync()
 		}
+
+		ce.Entry.Caller = zapcore.EntryCaller{
+			Defined:  defined,
+			PC:       frame.PC,
+			File:     frame.File,
+			Line:     frame.Line,
+			Function: frame.Function,
+		}
 	}
 	if log.addStack.Enabled(ce.Entry.Level) {
-		ce.Entry.Stack = Stack("").String
+		ce.Entry.Stack = StackSkip("", log.callerSkip+callerSkipOffset).String
 	}
 
 	return ce
 }
+
+// getCallerFrame gets caller frame. The argument skip is the number of stack
+// frames to ascend, with 0 identifying the caller of getCallerFrame. The
+// boolean ok is false if it was not possible to recover the information.
+//
+// Note: This implementation is similar to runtime.Caller, but it returns the whole frame.
+func getCallerFrame(skip int) (frame runtime.Frame, ok bool) {
+	const skipOffset = 2 // skip getCallerFrame and Callers
+
+	pc := make([]uintptr, 1)
+	numFrames := runtime.Callers(skip+skipOffset, pc[:])
+	if numFrames < 1 {
+		return
+	}
+
+	frame, _ = runtime.CallersFrames(pc).Next()
+	return frame, frame.PC != 0
+}

logger_test.go

@@ -366,10 +366,89 @@ func TestLoggerAddCaller(t *testing.T) {
 	}
 }
 
+func TestLoggerAddCallerFunction(t *testing.T) {
+	tests := []struct {
+		options         []Option
+		loggerFunction  string
+		sugaredFunction string
+	}{
+		{
+			options:         opts(),
+			loggerFunction:  "",
+			sugaredFunction: "",
+		},
+		{
+			options:         opts(WithCaller(false)),
+			loggerFunction:  "",
+			sugaredFunction: "",
+		},
+		{
+			options:         opts(AddCaller()),
+			loggerFunction:  "go.uber.org/zap.infoLog",
+			sugaredFunction: "go.uber.org/zap.infoLogSugared",
+		},
+		{
+			options:         opts(AddCaller(), WithCaller(false)),
+			loggerFunction:  "",
+			sugaredFunction: "",
+		},
+		{
+			options:         opts(WithCaller(true)),
+			loggerFunction:  "go.uber.org/zap.infoLog",
+			sugaredFunction: "go.uber.org/zap.infoLogSugared",
+		},
+		{
+			options:         opts(WithCaller(true), WithCaller(false)),
+			loggerFunction:  "",
+			sugaredFunction: "",
+		},
+		{
+			options:         opts(AddCaller(), AddCallerSkip(1), AddCallerSkip(-1)),
+			loggerFunction:  "go.uber.org/zap.infoLog",
+			sugaredFunction: "go.uber.org/zap.infoLogSugared",
+		},
+		{
+			options:         opts(AddCaller(), AddCallerSkip(2)),
+			loggerFunction:  "go.uber.org/zap.withLogger",
+			sugaredFunction: "go.uber.org/zap.withLogger",
+		},
+		{
+			options:         opts(AddCaller(), AddCallerSkip(2), AddCallerSkip(3)),
+			loggerFunction:  "runtime.goexit",
+			sugaredFunction: "runtime.goexit",
+		},
+	}
+	for _, tt := range tests {
+		withLogger(t, DebugLevel, tt.options, func(logger *Logger, logs *observer.ObservedLogs) {
+			// Make sure that sugaring and desugaring resets caller skip properly.
+			logger = logger.Sugar().Desugar()
+			infoLog(logger, "")
+			infoLogSugared(logger.Sugar(), "")
+			infoLog(logger.Sugar().Desugar(), "")
+
+			entries := logs.AllUntimed()
+			assert.Equal(t, 3, len(entries), "Unexpected number of logs written out.")
+			for _, entry := range []observer.LoggedEntry{entries[0], entries[2]} {
+				assert.Regexp(
+					t,
+					tt.loggerFunction,
+					entry.Entry.Caller.Function,
+					"Expected to find function name in output.",
+				)
+			}
+			assert.Regexp(
+				t,
+				tt.sugaredFunction,
+				entries[1].Entry.Caller.Function,
+				"Expected to find function name in output.",
+			)
+		})
+	}
+}
+
 func TestLoggerAddCallerFail(t *testing.T) {
 	errBuf := &ztest.Buffer{}
-	withLogger(t, DebugLevel, opts(AddCaller(), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) {
-		log.callerSkip = 1e3
+	withLogger(t, DebugLevel, opts(AddCaller(), AddCallerSkip(1e3), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) {
 		log.Info("Failure.")
 		assert.Regexp(
 			t,
@@ -382,6 +461,11 @@ func TestLoggerAddCallerFail(t *testing.T) {
 			logs.AllUntimed()[0].Entry.Message,
 			"Failure.",
 			"Expected original message to survive failures in runtime.Caller.")
+		assert.Equal(
+			t,
+			logs.AllUntimed()[0].Entry.Caller.Function,
+			"",
+			"Expected function name to be empty string.")
 	})
 }
 
@@ -450,3 +534,56 @@ func TestLoggerConcurrent(t *testing.T) {
 		}
 	})
 }
+
+func TestLoggerCustomOnFatal(t *testing.T) {
+	tests := []struct {
+		msg          string
+		onFatal      zapcore.CheckWriteAction
+		recoverValue interface{}
+	}{
+		{
+			msg:          "panic",
+			onFatal:      zapcore.WriteThenPanic,
+			recoverValue: "fatal",
+		},
+		{
+			msg:          "goexit",
+			onFatal:      zapcore.WriteThenGoexit,
+			recoverValue: nil,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.msg, func(t *testing.T) {
+			withLogger(t, InfoLevel, opts(OnFatal(tt.onFatal)), func(logger *Logger, logs *observer.ObservedLogs) {
+
+				var finished bool
+				recovered := make(chan interface{})
+				go func() {
+					defer func() {
+						recovered <- recover()
+					}()
+
+					logger.Fatal("fatal")
+					finished = true
+				}()
+
+				assert.Equal(t, tt.recoverValue, <-recovered, "unexpected value from recover()")
+				assert.False(t, finished, "expect goroutine to not finish after Fatal")
+
+				assert.Equal(t, []observer.LoggedEntry{{
+					Entry:   zapcore.Entry{Level: FatalLevel, Message: "fatal"},
+					Context: []Field{},
+				}}, logs.AllUntimed(), "unexpected logs")
+			})
+		})
+	}
+}
+
+func infoLog(logger *Logger, msg string, fields ...Field) {
+	logger.Info(msg, fields...)
+}
+
+func infoLogSugared(logger *SugaredLogger, args ...interface{}) {
+	logger.Info(args...)
+}