Add New Function Log Entry #844

wijayaerick · 2020-06-25T09:56:21Z

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 · 2020-06-25T09:56:26Z

All committers have signed the CLA.

codecov · 2020-06-25T10:00:52Z

Codecov Report

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

@@            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.

prashantv

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

logger.go

prashantv · 2020-07-16T15:48:39Z

logger_test.go

+	}{
+		{opts(), `^$`},
+		{opts(WithFunction(false)), `^$`},
+		{opts(AddFunction()), `zap.TestLoggerAddFunction.func1$`},


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

prashantv · 2020-07-16T15:51:34Z

logger_test.go

+func TestLoggerAddFunction(t *testing.T) {
+	tests := []struct {
+		options []Option
+		pat     string


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?

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

prashantv · 2020-07-16T15:53:43Z

logger_test.go

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


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

@prashantv done

prashantv · 2020-07-16T15:54:30Z

logger_test.go

+			t,
+			logs.AllUntimed()[0].Entry.Message,
+			"Failure.",
+			"Expected original message to survive failures in runtime.Caller.")


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

@prashantv done

prashantv · 2020-07-16T15:55:59Z

options.go

+// 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)
+}


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

prashantv · 2020-07-16T15:56:46Z

zapcore/console_encoder.go

@@ -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)


the FunctionKey is not being used

prashantv · 2020-07-16T15:58:08Z

zapcore/entry.go

@@ -147,6 +147,7 @@ type Entry struct {
 	LoggerName string
 	Message    string
 	Caller     EntryCaller
+	Function   string


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

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 · 2020-07-17T09:06:52Z

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 · 2020-07-18T18:13:09Z

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 · 2020-07-24T14:46:18Z

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

prashantv · 2020-07-28T05:50:41Z

logger.go

+		numFrames := runtime.Callers(log.callerSkip+callerSkipOffset+1, pc)
+		frame, _ := runtime.CallersFrames(pc[:numFrames]).Next()
+		defined := frame.PC != 0
+		if !defined {


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)

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

prashantv · 2020-07-28T05:52:52Z

logger.go

+		ce.Entry.Caller = zapcore.NewEntryCaller(frame.PC, frame.File, frame.Line, defined)
+		ce.Entry.Caller.Function = frame.Function


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)

thanks @prashantv updated

prashantv

LGTM, thanks @wijayaerick!

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

logger.go

Co-authored-by: Prashant Varanasi <[email protected]>

logger.go

Co-authored-by: Abhinav Gupta <[email protected]>

prashantv reviewed Jul 16, 2020

View reviewed changes

wijayaerick force-pushed the function-name branch from 9a1f58d to 9c616d5 Compare July 24, 2020 10:37

wijayaerick added 3 commits July 24, 2020 17:54

Add New Function Entry

3102620

Add Function in EntryCaller

914f3fa

TestConsoleSeparator with function

dafe1a2

wijayaerick force-pushed the function-name branch from 9c616d5 to dafe1a2 Compare July 24, 2020 11:00

prashantv reviewed Jul 28, 2020

View reviewed changes

Handle zero numFrames and refactor logic

4f80d89

prashantv approved these changes Aug 3, 2020

View reviewed changes

logger.go Show resolved Hide resolved

Add note about runtime.Caller in getCallerFrame

4200910

Co-authored-by: Prashant Varanasi <[email protected]>

abhinav approved these changes Aug 3, 2020

View reviewed changes

logger.go Outdated Show resolved Hide resolved

Add comment explaining skipOffset

bfdedf9

Co-authored-by: Abhinav Gupta <[email protected]>

prashantv merged commit 2314926 into uber-go:master Aug 14, 2020

ganeshskudva mentioned this pull request Mar 1, 2021

How to get function name in log output ? #925

Open

dependabot bot mentioned this pull request Mar 15, 2021

Bump go.uber.org/zap from 1.13.0 to 1.16.0 Sifchain/sifnode#950

Closed

cgxxv pushed a commit to cgxxv/zap that referenced this pull request Mar 25, 2022

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

c8d39cd

github-actions bot mentioned this pull request Apr 10, 2022

Link Checker Report scylladb/scylla-manager#3102

Closed

github-actions bot mentioned this pull request Apr 17, 2022

Link Checker Report scylladb/scylla-manager#3121

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add New Function Log Entry #844

Add New Function Log Entry #844

wijayaerick commented Jun 25, 2020

CLAassistant commented Jun 25, 2020 •

edited

Loading

codecov bot commented Jun 25, 2020 •

edited

Loading

prashantv left a comment

prashantv Jul 16, 2020

prashantv Jul 16, 2020

wijayaerick Jul 21, 2020 •

edited

Loading

prashantv Jul 16, 2020

wijayaerick Jul 24, 2020

prashantv Jul 16, 2020

wijayaerick Jul 24, 2020

prashantv Jul 16, 2020

prashantv Jul 16, 2020

prashantv Jul 16, 2020

wijayaerick Jul 17, 2020

wijayaerick commented Jul 17, 2020 •

edited

Loading

prashantv commented Jul 18, 2020

wijayaerick commented Jul 24, 2020

prashantv Jul 28, 2020

wijayaerick Jul 29, 2020

prashantv Jul 28, 2020

wijayaerick Jul 29, 2020

prashantv left a comment

		ce.Entry.Caller = zapcore.NewEntryCaller(frame.PC, frame.File, frame.Line, defined)
		ce.Entry.Caller.Function = frame.Function

Add New Function Log Entry #844

Add New Function Log Entry #844

Conversation

wijayaerick commented Jun 25, 2020

CLAassistant commented Jun 25, 2020 • edited Loading

codecov bot commented Jun 25, 2020 • edited Loading

Codecov Report

prashantv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wijayaerick Jul 21, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wijayaerick commented Jul 17, 2020 • edited Loading

prashantv commented Jul 18, 2020

wijayaerick commented Jul 24, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv left a comment

Choose a reason for hiding this comment

CLAassistant commented Jun 25, 2020 •

edited

Loading

codecov bot commented Jun 25, 2020 •

edited

Loading

wijayaerick Jul 21, 2020 •

edited

Loading

wijayaerick commented Jul 17, 2020 •

edited

Loading