Add New Function Log Entry (uber-go#844)

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,

logger.go

@@ -297,15 +297,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
 	}
 
 	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,11 @@ func TestLoggerConcurrent(t *testing.T) {
 		}
 	})
 }
+
+func infoLog(logger *Logger, msg string, fields ...Field) {
+	logger.Info(msg, fields...)
+}
+
+func infoLogSugared(logger *SugaredLogger, args ...interface{}) {
+	logger.Info(args...)
+}

options.go

@@ -86,15 +86,15 @@ func Development() Option {
 	})
 }
 
-// AddCaller configures the Logger to annotate each message with the filename
-// and line number of zap's caller.  See also WithCaller.
+// AddCaller configures the Logger to annotate each message with the filename,
+// line number, and function name of zap's caller. See also WithCaller.
 func AddCaller() Option {
 	return WithCaller(true)
 }
 
-// WithCaller configures the Logger to annotate each message with the filename
-// and line number of zap's caller, or not, depending on the value of enabled.
-// This is a generalized form of AddCaller.
+// WithCaller configures the Logger to annotate each message with the filename,
+// line number, and function name of zap's caller, or not, depending on the
+// value of enabled. This is a generalized form of AddCaller.
 func WithCaller(enabled bool) Option {
 	return optionFunc(func(log *Logger) {
 		log.addCaller = enabled

zapcore/console_encoder.go

@@ -93,8 +93,13 @@ func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer,
 
 		nameEncoder(ent.LoggerName, arr)
 	}
-	if ent.Caller.Defined && c.CallerKey != "" && c.EncodeCaller != nil {
-		c.EncodeCaller(ent.Caller, arr)
+	if ent.Caller.Defined {
+		if c.CallerKey != "" && c.EncodeCaller != nil {
+			c.EncodeCaller(ent.Caller, arr)
+		}
+		if c.FunctionKey != "" {
+			arr.AppendString(ent.Caller.Function)
+		}
 	}
 	for i := range arr.elems {
 		if i > 0 {

zapcore/console_encoder_test.go

@@ -33,7 +33,7 @@ var (
 		Message:    `hello`,
 		Time:       _epoch,
 		Stack:      "fake-stack",
-		Caller:     EntryCaller{Defined: true, File: "foo.go", Line: 42},
+		Caller:     EntryCaller{Defined: true, File: "foo.go", Line: 42, Function: "foo.Foo"},
 	}
 )
 
@@ -46,22 +46,22 @@ func TestConsoleSeparator(t *testing.T) {
 		{
 			desc:        "space console separator",
 			separator:   " ",
-			wantConsole: "0 info main foo.go:42 hello\nfake-stack\n",
+			wantConsole: "0 info main foo.go:42 foo.Foo hello\nfake-stack\n",
 		},
 		{
 			desc:        "default console separator",
 			separator:   "",
-			wantConsole: "0\tinfo\tmain\tfoo.go:42\thello\nfake-stack\n",
+			wantConsole: "0\tinfo\tmain\tfoo.go:42\tfoo.Foo\thello\nfake-stack\n",
 		},
 		{
 			desc:        "tag console separator",
 			separator:   "\t",
-			wantConsole: "0\tinfo\tmain\tfoo.go:42\thello\nfake-stack\n",
+			wantConsole: "0\tinfo\tmain\tfoo.go:42\tfoo.Foo\thello\nfake-stack\n",
 		},
 		{
 			desc:        "dash console separator",
 			separator:   "--",
-			wantConsole: "0--info--main--foo.go:42--hello\nfake-stack\n",
+			wantConsole: "0--info--main--foo.go:42--foo.Foo--hello\nfake-stack\n",
 		},
 	}
 

zapcore/encoder.go

@@ -317,6 +317,7 @@ type EncoderConfig struct {
 	TimeKey       string `json:"timeKey" yaml:"timeKey"`
 	NameKey       string `json:"nameKey" yaml:"nameKey"`
 	CallerKey     string `json:"callerKey" yaml:"callerKey"`
+	FunctionKey   string `json:"functionKey" yaml:"functionKey"`
 	StacktraceKey string `json:"stacktraceKey" yaml:"stacktraceKey"`
 	LineEnding    string `json:"lineEnding" yaml:"lineEnding"`
 	// Configure the primitive representations of common complex types. For