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

Conversation

wijayaerick
Copy link
Contributor

This PR introduces function name in log entry, as mentioned in #716.

Example:

// json
{"level":"info","ts":1593078683.653034,"caller":"foo/foo_test.go:13","func":"go.uber.org/zap/foo.TestFunc","msg":"message"}

// console
2020-06-25T16:51:23.653+0700	INFO	foo/foo_test.go:14	go.uber.org/zap/foo.TestFunc	message

@CLAassistant
Copy link

CLAassistant commented Jun 25, 2020

CLA assistant check
All committers have signed the CLA.

@codecov
Copy link

codecov bot commented Jun 25, 2020

Codecov Report

Merging #844 into master will increase coverage by 0.01%.
The diff coverage is 100.00%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #844      +/-   ##
==========================================
+ Coverage   98.35%   98.36%   +0.01%     
==========================================
  Files          43       43              
  Lines        2368     2391      +23     
==========================================
+ Hits         2329     2352      +23     
  Misses         32       32              
  Partials        7        7              
Impacted Files Coverage Δ
options.go 100.00% <ø> (ø)
zapcore/encoder.go 88.23% <ø> (ø)
zapcore/entry.go 94.50% <ø> (ø)
config.go 100.00% <100.00%> (ø)
logger.go 95.20% <100.00%> (+0.60%) ⬆️
zapcore/console_encoder.go 100.00% <100.00%> (ø)
zapcore/json_encoder.go 100.00% <100.00%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 53a3870...bfdedf9. Read the comment docs.

Copy link
Collaborator

@prashantv prashantv left a comment

Choose a reason for hiding this comment

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

Thanks you for the contribution @wijayaerick!

It looks great overall, the only design question I'm trying to decide is whether Function be part of the EntryCaller struct, with the function key always specified, but not encoded (for backwards compatibility) by leaving the default encode fields to skip.

This would allow us to reuse AddCaller and WithCaller, and assumes that there's no additional performance impact to get the function name when we're already getting the caller information.

config.go Show resolved Hide resolved
config.go Show resolved Hide resolved
logger.go Outdated Show resolved Hide resolved
logger_test.go Outdated
}{
{opts(), `^$`},
{opts(WithFunction(false)), `^$`},
{opts(AddFunction()), `zap.TestLoggerAddFunction.func1$`},
Copy link
Collaborator

Choose a reason for hiding this comment

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

To avoid relying on the internal function names used when anonymous functions are used, can you put the log calls into a separate function in this file, like func infoLog(logger *logger.Logger) and that way, we can compare this to a value we control

logger_test.go Outdated
func TestLoggerAddFunction(t *testing.T) {
tests := []struct {
options []Option
pat string
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can we use == to compare the Function output? Is there parts of the output that we don't control? I think the function is just package.function?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, we can use ==
The example output is go.uber.org/zap.infoLog, there should not be parts of the output that we don't control
Thanks for the suggestion

logger_test.go Outdated
func TestLoggerAddFunctionFail(t *testing.T) {
errBuf := &ztest.Buffer{}
withLogger(t, DebugLevel, opts(AddFunction(), ErrorOutput(errBuf)), func(log *Logger, logs *observer.ObservedLogs) {
log.callerSkip = 1e3
Copy link
Collaborator

Choose a reason for hiding this comment

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

instead of accessing the internals, can you do AddCallerSkip(1e3)?

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

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

options.go Outdated
Comment on lines 104 to 108
// AddFunction configures the Logger to annotate each message with the function
// name of zap's caller. See also WithFunction.
func AddFunction() Option {
return WithFunction(true)
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

We have both AddCaller and WithCaller for backwards compatibility reasons (WithCaller was added later, and we couldn't remove AddCaller without breaking the API).

In this case, since this is a new API, only adding WithFunction would be preferred

@@ -92,6 +92,9 @@ func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer,
if ent.Caller.Defined && c.CallerKey != "" && c.EncodeCaller != nil {
c.EncodeCaller(ent.Caller, arr)
}
if ent.Function != "" && c.FunctionKey != "" {
arr.AppendString(ent.Function)
Copy link
Collaborator

Choose a reason for hiding this comment

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

the FunctionKey is not being used

zapcore/entry.go Outdated
@@ -147,6 +147,7 @@ type Entry struct {
LoggerName string
Message string
Caller EntryCaller
Function string
Copy link
Collaborator

Choose a reason for hiding this comment

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

Perhaps Function be a part of the EntryCaller struct, since it's additional metadata related to the caller?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I had the same thought while I was implementing this. I think I was confused in the past and so I ended up putting Function as a log entry instead of being part of EntryCaller.

Now I think again, it is reasonable to put Function as part of EntryCaller.

@wijayaerick
Copy link
Contributor Author

wijayaerick commented Jul 17, 2020

This would allow us to reuse AddCaller and WithCaller, and assumes that there's no additional performance impact to get the function name when we're already getting the caller information.

@prashantv
So, by putting Function in EntryCaller, we do not need to define AddFunction and WithFunction. Instead, AddCaller will add both "caller" and "function". If users want to disable just caller or just function, they set the respective encoder config key to OmitKey.

Is this what you mean? I just want to confirm.

@prashantv
Copy link
Collaborator

This would allow us to reuse AddCaller and WithCaller, and assumes that there's no additional performance impact to get the function name when we're already getting the caller information.

@prashantv
So, by putting Function in EntryCaller, we do not need to define AddFunction and WithFunction. Instead, AddCaller will add both "caller" and "function". If users want to disable just caller or just function, they set the respective encoder config key to OmitKey.

Is this what you mean? I just want to confirm.

Yes, exactly. For backwards compatibility, we may need to leave the default values in the encoder configuration for function to be OmitKey, but it's something they can enable via configuration (no additional options passed to the logger construction)

@wijayaerick
Copy link
Contributor Author

@prashantv Thank you for your detailed review comments.
I've updated the code, please have another look.

logger.go Outdated
Comment on lines 301 to 304
numFrames := runtime.Callers(log.callerSkip+callerSkipOffset+1, pc)
frame, _ := runtime.CallersFrames(pc[:numFrames]).Next()
defined := frame.PC != 0
if !defined {
Copy link
Collaborator

Choose a reason for hiding this comment

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

couple of things here:

  • do we need to handle the case where numFrames == 0 which is handled in the runtime (e.g., if someone sets skip too high)
  • let's move the logic into a separate function that returns a frame

Can we also add a comment for the frame.PC != 0 case (i think that's the "failed to decode case" according to the docs)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I completely missed that case... thanks for the suggestions, updated the code @prashantv
I've checked the benchmark, there should be no additional performance impact

logger.go Outdated
Comment on lines 309 to 310
ce.Entry.Caller = zapcore.NewEntryCaller(frame.PC, frame.File, frame.Line, defined)
ce.Entry.Caller.Function = frame.Function
Copy link
Collaborator

Choose a reason for hiding this comment

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

since we're setting fields anyway, we could just do zapcore.EntryCaller{PC: frame.PC, File: frame.File, ...} instead of using the constructor but then modifying (prefer to create once and use that instead of mutating the Entry.Caller)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

thanks @prashantv updated

Copy link
Collaborator

@prashantv prashantv left a comment

Choose a reason for hiding this comment

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

LGTM, thanks @wijayaerick!

I'll merge this in later in the week, so others can also review (cc @abhinav).

logger.go Show resolved Hide resolved
Co-authored-by: Prashant Varanasi <github@prashantv.com>
logger.go Outdated Show resolved Hide resolved
Co-authored-by: Abhinav Gupta <mail@abhinavg.net>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants