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

segevfiner · 2020-06-23T19:55:12Z

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 · 2020-06-23T19:55:16Z

All committers have signed the CLA.

codecov · 2020-06-23T19:59:47Z

Codecov Report

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

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

prashantv

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

field.go

segevfiner · 2020-07-22T08:49:16Z

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

prashantv · 2020-08-03T16:23:36Z

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 · 2020-08-03T18:15:11Z

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

abhinav

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

Also remove the zap frame skipping logic in favour of zap setting the skip correctly when taking the stack trace.

segevfiner · 2020-08-05T15:31:53Z

Made the requested change.

prashantv · 2020-08-12T04:09:16Z

stacktrace.go

 	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)


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

Leftover from still having skip zap frames.

stacktrace.go

abhinav

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.

abhinav · 2020-08-14T22:48:44Z

field_test.go

+	assertCanBeReused(t, f)
+}
+
+func TestStackSkipFieldWithSkip(t *testing.T) {


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

logger.go

abhinav · 2020-08-14T23:00:14Z

stacktrace_ext_test.go

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


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

abhinav · 2020-08-14T23:02:16Z

stacktrace_test.go

+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.")


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.")

abhinav · 2020-08-14T23:03:01Z

stacktrace_test.go

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


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).",

abhinav · 2020-08-14T23:03:31Z

stacktrace_test.go

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


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.")

abhinav · 2020-08-14T23:03:40Z

stacktrace_test.go

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


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.",

abhinav

LGTM

logger.go

prashantv · 2020-08-17T23:45:36Z

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 · 2020-08-18T00:57:21Z

@prashantv Updated.

…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

Introduce UseCallerSkipForStacktrace & StackSkip

017057e

* 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

prashantv reviewed Jul 22, 2020

View reviewed changes

stacktrace.go Outdated Show resolved Hide resolved

field.go Outdated Show resolved Hide resolved

segevfiner added 2 commits July 26, 2020 01:37

Change takeStacktrace skip parameter to a value

8e25507

Modify StackSkip doc

c27b7e4

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

segevfiner added 2 commits July 26, 2020 02:03

Added tests and fixed bugs

3410fce

Fix failing test

33c1b16

abhinav reviewed Aug 3, 2020

View reviewed changes

field.go Outdated Show resolved Hide resolved

field.go Outdated Show resolved Hide resolved

segevfiner force-pushed the use-caller-skip-for-stacktrace branch 2 times, most recently from a2a5f11 to 20dc3e4 Compare August 5, 2020 15:11

Make UseCallerSkipForStacktrace the default, removing the option

80d2017

Also remove the zap frame skipping logic in favour of zap setting the skip correctly when taking the stack trace.

segevfiner force-pushed the use-caller-skip-for-stacktrace branch from 20dc3e4 to 80d2017 Compare August 5, 2020 15:25

segevfiner requested a review from prashantv August 5, 2020 15:31

prashantv reviewed Aug 12, 2020

View reviewed changes

Code review fix

066ee2d

segevfiner requested a review from prashantv August 12, 2020 22:54

prashantv added the ready for second review label Aug 14, 2020

abhinav reviewed Aug 14, 2020

View reviewed changes

Code review fixes for tests

fc5ed1d

segevfiner requested a review from abhinav August 15, 2020 11:22

abhinav approved these changes Aug 17, 2020

View reviewed changes

prashantv approved these changes Aug 17, 2020

View reviewed changes

logger.go Show resolved Hide resolved

segevfiner changed the title ~~Introduce UseCallerSkipForStacktrace & StackSkip~~ Honor CallerSkip when taking stack traces & add the StackSkip field Aug 18, 2020

prashantv approved these changes Aug 18, 2020

View reviewed changes

prashantv merged commit 2657839 into uber-go:master Aug 18, 2020

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

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

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

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

segevfiner commented Jun 23, 2020 •

edited by prashantv

Loading

CLAassistant commented Jun 23, 2020 •

edited

Loading

codecov bot commented Jun 23, 2020 •

edited

Loading

prashantv left a comment

segevfiner commented Jul 22, 2020

prashantv commented Aug 3, 2020

segevfiner commented Aug 3, 2020 •

edited

Loading

abhinav left a comment

segevfiner commented Aug 5, 2020

prashantv Aug 12, 2020

segevfiner Aug 12, 2020

abhinav left a comment

abhinav Aug 14, 2020

abhinav Aug 14, 2020

abhinav Aug 14, 2020

abhinav Aug 14, 2020

abhinav Aug 14, 2020

abhinav Aug 14, 2020

abhinav left a comment

prashantv commented Aug 17, 2020

segevfiner commented Aug 18, 2020

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

	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.")

	"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).",

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

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

Conversation

segevfiner commented Jun 23, 2020 • edited by prashantv Loading

CLAassistant commented Jun 23, 2020 • edited Loading

codecov bot commented Jun 23, 2020 • edited Loading

Codecov Report

prashantv left a comment

Choose a reason for hiding this comment

segevfiner commented Jul 22, 2020

prashantv commented Aug 3, 2020

segevfiner commented Aug 3, 2020 • edited Loading

abhinav left a comment

Choose a reason for hiding this comment

segevfiner commented Aug 5, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhinav left a 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

abhinav left a comment

Choose a reason for hiding this comment

prashantv commented Aug 17, 2020

segevfiner commented Aug 18, 2020

segevfiner commented Jun 23, 2020 •

edited by prashantv

Loading

CLAassistant commented Jun 23, 2020 •

edited

Loading

codecov bot commented Jun 23, 2020 •

edited

Loading

segevfiner commented Aug 3, 2020 •

edited

Loading