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 all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions config.go
Original file line number Diff line number Diff line change
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
30 changes: 28 additions & 2 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
wijayaerick marked this conversation as resolved.
Show resolved Hide resolved
//
// 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
}
96 changes: 94 additions & 2 deletions logger_test.go
Original file line number Diff line number Diff line change
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
Original file line number Diff line number Diff line change
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
Original file line number Diff line number Diff line change
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
Original file line number Diff line number Diff line change
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
Original file line number Diff line number Diff line change
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
Loading