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

Honor CallerSkip when taking stack traces & add the StackSkip field #843

Merged
merged 8 commits into from
Aug 18, 2020

Conversation

segevfiner
Copy link
Contributor

@segevfiner segevfiner commented Jun 23, 2020

  • Honor CallerSkip when taking a stack trace. Both the caller and stack trace will now point to the same frame.
  • Add StackSkip which is similar to Stack but allows skipping frames from the top of the stack.

This removes the internal behavior of skipping zap specific stack frames when taking a stack trace, and instead relies on the same behavior used to calculate the number of frames to skip for getting the caller to also skip frames in the stack trace.

Fixes #512, fixes #727

* UseCallerSkipForStacktrace configures the Logger to honor CallerSkip
when taking stacktraces.
* StackSkip is similar to Stack but allows
skipping frames from the top of the stack

Fixes uber-go#512, fixes uber-go#727
@CLAassistant
Copy link

CLAassistant commented Jun 23, 2020

CLA assistant check
All committers have signed the CLA.

@codecov
Copy link

codecov bot commented Jun 23, 2020

Codecov Report

Merging #843 into master will increase coverage by 0.02%.
The diff coverage is 100.00%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #843      +/-   ##
==========================================
+ Coverage   98.33%   98.35%   +0.02%     
==========================================
  Files          43       43              
  Lines        2349     2378      +29     
==========================================
+ Hits         2310     2339      +29     
  Misses         32       32              
  Partials        7        7              
Impacted Files Coverage Δ
field.go 100.00% <100.00%> (ø)
logger.go 95.20% <100.00%> (+0.60%) ⬆️
stacktrace.go 96.55% <100.00%> (-1.33%) ⬇️
config.go 100.00% <0.00%> (ø)
zapcore/entry.go 94.50% <0.00%> (ø)
zapcore/json_encoder.go 100.00% <0.00%> (ø)
zapcore/console_encoder.go 100.00% <0.00%> (ø)
zapcore/encoder.go 88.23% <0.00%> (+1.96%) ⬆️

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 39aa3a1...fc5ed1d. 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 for taking this on @segevfiner

After reviewing, I have a couple of questions:

  • Do we need StackSkip: It's is not used or needed for the logger to skip stack frames based on caller skip, so doesn't seem too related to the change.
  • I think leaving the stacktrace pruning as-is is best for backwards compatibility

I think using an option is the right thing for backwards compatibility, although in this case, I think it may be more of a bug that the stacktrace attached skips zap stackframes, but doesn't take callerSkip into apply.

We should also get @abhinav's opinion on this -- would you prefer to leave the option (which likely means most users won't find this/enable this) which helps maintain compatibility exactly?

stacktrace.go Outdated Show resolved Hide resolved
field.go Outdated Show resolved Hide resolved
@segevfiner
Copy link
Contributor Author

* Do we need `StackSkip`: It's is not used or needed for the logger to skip stack frames based on caller skip, so doesn't seem too related to the change.

We don't have too, it's just for completeness. Zap takes a stack trace, and the user can take a stack using the Stack field and place it where he wants as well. So as Zap itself can take a stack trace while skipping frames, it makes sense to me that the user can also take a stack with a skip using a field and place it where he wants.

* I think leaving the stacktrace pruning as-is is best for backwards compatibility

I think using an option is the right thing for backwards compatibility, although in this case, I think it may be more of a bug that the stacktrace attached skips zap stackframes, but doesn't take callerSkip into apply.

That's why I kept it for the time being and why it's being a flag. Though I wonder if that flag is on should we also do zap stackframe pruning or rely on callerSkip being set correctly...

@segevfiner segevfiner force-pushed the use-caller-skip-for-stacktrace branch from 4169790 to c27b7e4 Compare July 25, 2020 22:38
@prashantv
Copy link
Collaborator

I discussed whether we should default UseCallerSkipForStacktrace with @abhinav last week, and we agreed that:

  • This is better behaviour by default
  • There may be some use-cases that are depending stack traces to include the frames, but it doesn't seem common

Given that, we agreed on:

  • Always use caller skip for stack trace as part of this change (this is effectively a bug fix)
  • If we get reports from users who rely on stack traces to not inherit skip, we'll add a future option (the implementation should allow for that flexibility, but not add the option yet)

Would you be able to update your change to match the above behaviour @segevfiner? Thanks!

@segevfiner
Copy link
Contributor Author

segevfiner commented Aug 3, 2020

@prashantv I can. I will just need to find some time for it. Effectively I'll be removing the option and moving to always use the new behavior.

The only problem part is the zap stack frame trimming which I kept to preserve the old behavior when the option is false, which will then only be used for the Stack field, we might want to remove it, but then if you would want to restore the option, you might have to restore that code later on. It will probably also fixing some tests and passing the skip correctly in the Stack field rather then relying on the old behavior.

Copy link
Collaborator

@abhinav abhinav left a comment

Choose a reason for hiding this comment

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

Besides minor stylistic comments, this is a good direction.

As @prashantv suggested, I'm in favor of making this the default behavior. We can add the flag later as needed.

field.go Outdated Show resolved Hide resolved
field.go Outdated Show resolved Hide resolved
@segevfiner segevfiner force-pushed the use-caller-skip-for-stacktrace branch 2 times, most recently from a2a5f11 to 20dc3e4 Compare August 5, 2020 15:11
Also remove the zap frame skipping logic in favour of zap setting the
skip correctly when taking the stack trace.
@segevfiner
Copy link
Contributor Author

Made the requested change.

stacktrace.go Outdated
buffer := bufferpool.Get()
defer buffer.Free()
programCounters := _stacktracePool.Get().(*programCounters)
defer _stacktracePool.Put(programCounters)

var numFrames int
for {
// Skip the call to runtime.Counters and takeStacktrace so that the
// Skip the call to runtime.Callers and takeStacktrace so that the
// program counters start at the caller of takeStacktrace.
numFrames = runtime.Callers(2, programCounters.pcs)
Copy link
Collaborator

Choose a reason for hiding this comment

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

why do we implement skip manually below, can't we just add it here?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Leftover from still having skip zap frames.

stacktrace.go Show resolved Hide resolved
Copy link
Collaborator

@abhinav abhinav left a comment

Choose a reason for hiding this comment

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

This looks great! I have some minor fix-ups for some of the tests, and it looks like TestStackSkipField and TestStackSkipfieldWithSkip are unintentionally the same.

assertCanBeReused(t, f)
}

func TestStackSkipFieldWithSkip(t *testing.T) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

There doesn't appear to be any difference between this and TestStackSkipField. Did you mean to use zero for TestStackSkipField?

logger.go Show resolved Hide resolved
Comment on lines 129 to 130
require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much")
require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip", "Should not skip too much")
Copy link
Collaborator

Choose a reason for hiding this comment

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

If we pass the first check, we'll always also pass the second check. We can probably just drop the second.

Suggested change
require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much")
require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip", "Should not skip too much")
require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much")

func TestTakeStacktraceWithSkip(t *testing.T) {
trace := takeStacktrace(1)
lines := strings.Split(trace, "\n")
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
Copy link
Collaborator

Choose a reason for hiding this comment

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

minor: Can use NotEmpty.

Suggested change
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
require.NotEmpty(t, lines, "Expected stacktrace to have at least one frame.")

t,
lines[0],
"testing.",
"Expected stacktrace to start with the test runner (skipping our own frame) %s.", lines[0],
Copy link
Collaborator

Choose a reason for hiding this comment

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

minor: Testify will include the lines[0] in the output so we don't need to.

Suggested change
"Expected stacktrace to start with the test runner (skipping our own frame) %s.", lines[0],
"Expected stacktrace to start with the test runner (skipping our own frame).",

trace = takeStacktrace(2)
}()
lines := strings.Split(trace, "\n")
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
Copy link
Collaborator

Choose a reason for hiding this comment

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

Suggested change
require.True(t, len(lines) > 0, "Expected stacktrace to have at least one frame.")
require.NotEmpty(t, lines, "Expected stacktrace to have at least one frame.")

t,
lines[0],
"testing.",
"Expected stacktrace to start with the test function (skipping the test function) %s.", lines[0],
Copy link
Collaborator

Choose a reason for hiding this comment

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

Suggested change
"Expected stacktrace to start with the test function (skipping the test function) %s.", lines[0],
"Expected stacktrace to start with the test function (skipping the test function.",

Copy link
Collaborator

@abhinav abhinav left a comment

Choose a reason for hiding this comment

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

LGTM

logger.go Show resolved Hide resolved
@prashantv
Copy link
Collaborator

The change looks good! Can we update the title / summary to reflect the changes made during code review (we now always respect caller skip when taking stack traces as part of an entry)

@segevfiner segevfiner changed the title Introduce UseCallerSkipForStacktrace & StackSkip Honor CallerSkip when taking stack traces & add the StackSkip field Aug 18, 2020
@segevfiner
Copy link
Contributor Author

@prashantv Updated.

@prashantv prashantv merged commit 2657839 into uber-go:master Aug 18, 2020
cgxxv pushed a commit to cgxxv/zap that referenced this pull request Mar 25, 2022
…ber-go#843)

* Honor `CallerSkip` when taking a stack trace. Both the caller and stack trace will now point to the same frame.
* Add `StackSkip` which is similar to `Stack` but allows skipping frames from the top of the stack.

This removes the internal behavior of skipping zap specific stack frames when taking a stack trace, and instead relies on the same behavior used to calculate the number of frames to skip for getting the caller to also skip frames in the stack trace.

Fixes uber-go#512, fixes uber-go#727
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging this pull request may close these issues.

Add an option for setting stack skip CallerSkip does not apply to stacktraces captured by zap
4 participants