Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add New Function Log Entry #844

Merged
merged 6 commits into from Aug 14, 2020
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 2 additions & 0 deletions config.go
Expand Up @@ -101,6 +101,7 @@ func NewProductionEncoderConfig() zapcore.EncoderConfig {
LevelKey: "level",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey,
prashantv marked this conversation as resolved.
Show resolved Hide resolved
MessageKey: "msg",
StacktraceKey: "stacktrace",
LineEnding: zapcore.DefaultLineEnding,
Expand Down Expand Up @@ -140,6 +141,7 @@ func NewDevelopmentEncoderConfig() zapcore.EncoderConfig {
LevelKey: "L",
NameKey: "N",
CallerKey: "C",
FunctionKey: zapcore.OmitKey,
prashantv marked this conversation as resolved.
Show resolved Hide resolved
MessageKey: "M",
StacktraceKey: "S",
LineEnding: zapcore.DefaultLineEnding,
Expand Down
28 changes: 26 additions & 2 deletions logger.go
Expand Up @@ -297,15 +297,39 @@ 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.
wijayaerick marked this conversation as resolved.
Show resolved Hide resolved
func getCallerFrame(skip int) (frame runtime.Frame, ok bool) {
const skipOffset = 2
wijayaerick marked this conversation as resolved.
Show resolved Hide resolved

pc := make([]uintptr, 1)
numFrames := runtime.Callers(skip+skipOffset, pc[:])
if numFrames < 1 {
return
}

frame, _ = runtime.CallersFrames(pc).Next()
return frame, frame.PC != 0
}
96 changes: 94 additions & 2 deletions logger_test.go
Expand Up @@ -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,
Expand All @@ -382,6 +461,11 @@ func TestLoggerAddCallerFail(t *testing.T) {
logs.AllUntimed()[0].Entry.Message,
"Failure.",
"Expected original message to survive failures in runtime.Caller.")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can you also verify that the Function is set to an empty string in the failure case

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@prashantv done

assert.Equal(
t,
logs.AllUntimed()[0].Entry.Caller.Function,
"",
"Expected function name to be empty string.")
})
}

Expand Down Expand Up @@ -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...)
}
10 changes: 5 additions & 5 deletions options.go
Expand Up @@ -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
Expand Down
9 changes: 7 additions & 2 deletions zapcore/console_encoder.go
Expand Up @@ -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 {
Expand Down
10 changes: 5 additions & 5 deletions zapcore/console_encoder_test.go
Expand Up @@ -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"},
}
)

Expand All @@ -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",
},
}

Expand Down
1 change: 1 addition & 0 deletions zapcore/encoder.go
Expand Up @@ -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
Expand Down