Add finer grained caller annotation support #227
Conversation
|
@jcorbin, thanks for your PR! By analyzing the history of the files in this pull request, we identified @akshayjshah, @tamird and @noxiouz to be potential reviewers. |
jcorbin
force-pushed
the
jcorbin.callerskip
branch
from
322fb2d to
e891704
Compare
|
Okay, dropped the field, and added a test for the new option. N.B. how I avoided coupling to line numbers by moving utility code into a new file; if you'd rather just use line numbers, we can go back to bb641cd. |
jcorbin
force-pushed
the
jcorbin.callerskip
branch
from
7148461 to
0e5f259
Compare
| withJSONLogger(t, DebugLevel, opts(AddCallerSkip(1)), func(logger Logger, buf *testBuffer) { | ||
| logger.Info("Callers.") | ||
| assert.Regexp(t, | ||
| `"caller":"[^"]+/common_test.go:\d+","msg":"Callers\."`, |
There was a problem hiding this comment.
Let's also test that
if ce := logger.Check(InfoLevel, "Callers"); ce != nil {
ce.Write()
}
gets the correct caller. This should be the long-awaited fix for #40.
| return optionFunc(func(log *logger) { | ||
| log.addCaller = true | ||
| if n := skip + _defaultCallerSkip; n > log.callerSkip { | ||
| log.callerSkip = n | ||
| } |
There was a problem hiding this comment.
I think of these as orthogonal options: AddCaller is for users to indicate that they'd like to include caller names, and AddCallerSkip is for extension authors to make sure that the logged caller is accurate. I imagine wrapper authors, including the proposed sugared logger, taking a slice of options from the user and adding on AddCallerSkip(n) (to account for the frames occupied by their wrapper) before passing the result on to the inner logger constructor (which might itself be a wrapper).
Given that, I think that this option should just do log.callerSkip += skip.
| @@ -144,7 +144,7 @@ func (log *logger) Check(lvl Level, msg string) *CheckedEntry { | |||
| ce.ErrorOutput = log.errorOutput | |||
|
|
|||
| if log.addCaller { | |||
| ce.Entry.Caller = MakeEntryCaller(runtime.Caller(log.callerSkip)) | |||
| ce.Entry.Caller = MakeEntryCaller(runtime.Caller(log.callerSkip + 2)) | |||
There was a problem hiding this comment.
Can we preserve the defaultCallerSkip constant instead of putting a literal 2 here?
There was a problem hiding this comment.
Well, I'd argue for leaving it in place:
- it truly is path dependent on how
loggercallscheck - originally I started out with it as a third arg to the new
checkmethod... - ...which was either 2 or 3 depending on the entry path call site to
check - however, after I modified all the named entries (Debug, Info, Warn, etc) to call
checkinstead ofLog, it turned out that all the sites were passing the same2skip arg
I'd be happy to re-introduce a constant, but:
- it doesn't deserve to be package level any more
- rather it would be at the top of
check, and called something likeskipOffset
I'll do that since it'll dovetail with any future needs if we ever need to re-promote it to a third check arg.
| if ce := log.check(FatalLevel, msg); ce != nil { | ||
| ce.Write(fields...) | ||
| } | ||
| } |
There was a problem hiding this comment.
Yuck. I suppose this is a necessary evil to keep the skip level consistent.
There was a problem hiding this comment.
Yes it is, and this actually was an untested bug in prior (and I'm still lacking a case for it actually):
- Log is an entry point...
- ...but so are Debug, Info, etc.
So all the named entries need +1 more offset than Log ... but we have no support for dynamically modifying skip (and we're trying very hard to avoid adding such).
There was a problem hiding this comment.
Nvm the point about Log is an entry point: it's not, we dropped it in #201, but the implementation lived on here; will drop.
| testCase.name) | ||
| } | ||
|
|
||
| assert.Empty(t, errSink.String(), "Expected error sink to be empty.") |
There was a problem hiding this comment.
Can we structure this so that each test case includes the logger and the expected message, and in the test loop we
tt.logger.Info("foo")
tt.logger.Check(InfoLevel, "foo").Write()
and then assert that we got the expected message twice? Seems like that would more clearly associate the loggers and the expectations.
There was a problem hiding this comment.
Will do, this code is a bit more repetitive than prior because it's a "contraction" back away from a moment of too much indirection; I'll start layering back some ;-)
| // AddCallerSkip configures the Logger to annotate each message with the filename | ||
| // and line number of a caller outside of zap; which caller in the stack is | ||
| // controlled by the skip argument. If more than one AddCallerSkip option is | ||
| // provided, then the maximum skip amount is used. |
There was a problem hiding this comment.
nit: "the sum of the skip amounts is used." Also, to me the comment suggests that this option also enables caller annotations - may want to clarify.
* Add AddCallerSkip option * Improve and expand caller skip test * Fix logger Check v Level-log skipping * logger: drop old Log method; not actually part of the interface since #201
@akshayjshah let me know if you're okay with adding the new field support or not; if so I'll write tests, if not we'll just stop at the new option for now.
Towards #40