[e2e] Dump the stacktrace while an error occurs #80979

jiatongw · 2019-08-05T07:37:03Z

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

It's difficult to navigate when the error is generic, so dumping the stacktrace is worthwhile.
Reference: #34059

Does this PR introduce a user-facing change?:

NONE

jiatongw · 2019-08-05T07:37:51Z

/assign @timothysc @alejandrox1

jiatongw · 2019-08-05T07:38:58Z

/area e2e-test-framework
/area test
/sig testing

jiatongw · 2019-08-05T07:44:10Z

test/e2e/framework/util.go

@@ -1327,6 +1328,8 @@ func ExpectNoError(err error, explain ...interface{}) {
 func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) {
 	if err != nil {
 		e2elog.Logf("Unexpected error occurred: %v", err)
+		// Dump the stacktrace while an error occurs
+		debug.PrintStack()
 	}


Although panic could print the stacktrace but it will exit the program. So using debug.PrintStack() instead.

jiatongw · 2019-08-05T16:12:23Z

/retest

timothysc

I like it!
This will be helpful on errors.
/cc @johnSchnake
/lgtm
/approve

k8s-ci-robot · 2019-08-05T16:16:14Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: jiatongw, timothysc

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~test/e2e/framework/OWNERS~~ [timothysc]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

johnSchnake · 2019-08-05T16:21:34Z

test/e2e/framework/util.go

@@ -1340,6 +1343,8 @@ func ExpectNoErrorWithRetries(fn func() error, maxRetries int, explain ...interf
 			return
 		}
 		e2elog.Logf("(Attempt %d of %d) Unexpected error occurred: %v", i+1, maxRetries, err)
+		// Dump the stacktrace while an error occurs
+		debug.PrintStack()


If we're doing retries it seems like we expect errors and wouldn't want/need the stacktrace.

Can we move this down so that we only dump the trace here if we run out of retries and are actually bubbling up the error?

My thought is that it may have different reasons to cause the retry fail each time. So for each retry I chose to print the stack.

any comments?

Although that can happen; it has never been the case in my experience. Usually the same error happens 5 times so only the last one matters. OR you get an "error" which was somewhat expected (like polling for a service to come up) so you see 4 errors (and now 4 entire stack traces) even though the test goes onto pass.

My preference would still be for just the trace at the end, but I don't feel that strongly if you prefer this.

This make more sense. I will move the printstack() out of the loop

Let me know when you've made the changes and I'll re-review and remove the hold

Ready to re-review

johnSchnake · 2019-08-05T16:22:06Z

test/e2e/framework/util.go

@@ -1327,6 +1328,8 @@ func ExpectNoError(err error, explain ...interface{}) {
 func ExpectNoErrorWithOffset(offset int, err error, explain ...interface{}) {
 	if err != nil {
 		e2elog.Logf("Unexpected error occurred: %v", err)
+		// Dump the stacktrace while an error occurs


nit: I don't think the comments add any helpful information in either place. I'd just remove them.

Deleted the comment

timothysc · 2019-08-05T16:36:26Z

/hold

jiatongw · 2019-08-05T22:38:35Z

/retest

neolit123

i think that the PrintStack will be useful for all of our Expect wrappers - i.e. not only these two.

neolit123 · 2019-08-06T01:09:05Z

test/e2e/framework/util.go

@@ -1342,6 +1344,7 @@ func ExpectNoErrorWithRetries(fn func() error, maxRetries int, explain ...interf
 		}
 		e2elog.Logf("(Attempt %d of %d) Unexpected error occurred: %v", i+1, maxRetries, err)
 	}
+	debug.PrintStack()


should this PrintStack call should only happen if err != nil ?

@neolit123 For wrappers like ExpectEqual and ExpectNotEqual, we need to put the PrintStack into a condition statement to avoid it dump the stacktrace every time the wrappers be called. But gomega.Expect() has no return value. I don't have any better insights to do some change in the wrappers. But there is a potential way, similar like this: For those tests that call ExpectEqual/ExpectNotEqual, have a try..catch thing. If exception happens, then call PrintStack(). But Go doesn't have this kind of mechanism so this may involve a lot of changes. Or do you have any insights ?

Capture the stdout/stderr after ExpectEqual/ExpectNotEqual is also a potential solution. Need to implement a wrappers for the capture behavior.

sorry my comment here was about this.

should this PrintStack call should only happen if err != nil ?

if err != nil { debug.PrintStack() }

otherwise we are printing a stack trace even if there is no error in the retires.

ready to re-review

neolit123 · 2019-08-07T13:16:28Z

i think that the PrintStack will be useful for all of our Expect wrappers - i.e. not only these two.

@neolit123 For wrappers like ExpectEqual and ExpectNotEqual, we need to put the PrintStack into a condition statement to avoid it dump the stacktrace every time the wrappers be called

that's what i meant.
we already perform a similar check in the Expect* functions that this PR changes.

if we add similar checks it should work e.g.

// ExpectError expects an error happens, otherwise an exception raises
func ExpectError(err error, explain ...interface{}) {
    if err == nil {
       // PrintStack
    }
    gomega.Expect(err).To(gomega.HaveOccurred(), explain...)
}

these need reflection on the interfaces to see if they are of the same type and equal.

// ExpectEqual expects the specified two are the same, otherwise an exception raises
func ExpectEqual(actual interface{}, extra interface{}, explain ...interface{}) {
	gomega.Expect(actual).To(gomega.Equal(extra), explain...)
}

jiatongw · 2019-08-07T17:30:46Z

these need reflection on the interfaces to see if they are of the same type and equal.

// ExpectEqual expects the specified two are the same, otherwise an exception raises
func ExpectEqual(actual interface{}, extra interface{}, explain ...interface{}) {
	gomega.Expect(actual).To(gomega.Equal(extra), explain...)
}

That's a better solution. Thanks

neolit123

thanks for the update @jiatongw
/lgtm
but i'd prefer if someone else has a look too.
/assign @johnSchnake
/hold

jiatongw · 2019-08-09T19:34:47Z

/retest

johnSchnake · 2019-08-09T20:54:02Z

test/e2e/framework/util.go

+	if reflect.TypeOf(actual) != reflect.TypeOf(extra) {
+		e2elog.Logf("Unexpected unequal occurred: %v and %v", actual, extra)
+		debug.PrintStack()
+	} else if reflect.ValueOf(actual) != reflect.ValueOf(extra) {


This is not the type of comparison you want. From the godocs:

To compare two Values, compare the results of the Interface method. Using == on two Values does not compare the underlying values they represent.

I wouldn't even use the Interface since it gets confusing to anyone about when/how they can use certain reflect methods.

It seems like in these two cases we should be using the actual match that ginkgo will do, just leverage those without the Expect:

if isEqual, _ := gomega.Equal(extra).Match(actual); isEqual{ ... }

Double-check me on that syntax but I think thats the way it would be written.

Hi @johnSchnake , based on the doc https://onsi.github.io/gomega/#provided-matchers, I can't find a use like gomega.Equal(extra).Match(actual) but I think I can use reflect.DeepEqual to compare ACTUAL with EXPECTED, which is the gomega.Equal implementation.

They are all exported types/interfaces so we should just leverage what they've already written. For instance, they dont just do reflect.DeepEqual but have an optimization in place. I don't want to have to maintain a separate method which could drift and doesn't have any justification/benefit over using theirs.

//For details on writing custom matchers, check out: http://onsi.github.io/gomega/#adding-your-own-matchers type GomegaMatcher interface { Match(actual interface{}) (success bool, err error) FailureMessage(actual interface{}) (message string) ...

Equal matcher implementation:
https://github.com/kubernetes/kubernetes/blob/master/vendor/github.com/onsi/gomega/matchers/equal_matcher.go#L15-L28

@johnSchnake could you re-review? Thanks!

oomichi · 2019-08-17T00:24:01Z

/cc @oomichi

Signed-off-by: Jiatong Wang <wangjiatong@vmware.com>

johnSchnake · 2019-08-21T19:42:04Z

/lgtm
/hold cancel

k8s-ci-robot assigned alejandrox1 and timothysc Aug 5, 2019

k8s-ci-robot requested review from ixdy and krzyzacy August 5, 2019 07:38

k8s-ci-robot added area/e2e-test-framework Issues or PRs related to refactoring the kubernetes e2e test framework area/test sig/testing Categorizes an issue or PR as relevant to SIG Testing. and removed needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Aug 5, 2019

jiatongw commented Aug 5, 2019

View reviewed changes

timothysc added the priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete. label Aug 5, 2019

k8s-ci-robot removed the needs-priority Indicates a PR lacks a `priority/foo` label and requires one. label Aug 5, 2019

timothysc added this to the v1.16 milestone Aug 5, 2019

timothysc reviewed Aug 5, 2019

View reviewed changes

k8s-ci-robot requested a review from johnSchnake August 5, 2019 16:15

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 5, 2019

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Aug 5, 2019

johnSchnake reviewed Aug 5, 2019

View reviewed changes

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 5, 2019

timothysc removed lgtm "Looks good to me", indicates that a PR is ready to be merged. do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. labels Aug 5, 2019

jiatongw force-pushed the e2e/framework/printstack branch from 2c59b25 to cd048e3 Compare August 5, 2019 21:57

neolit123 reviewed Aug 6, 2019

View reviewed changes

jiatongw force-pushed the e2e/framework/printstack branch from cd048e3 to b501b34 Compare August 9, 2019 18:00

k8s-ci-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Aug 9, 2019

jiatongw force-pushed the e2e/framework/printstack branch from 3ba9716 to a9ce198 Compare August 9, 2019 18:20

neolit123 reviewed Aug 9, 2019

View reviewed changes

k8s-ci-robot assigned johnSchnake Aug 9, 2019

k8s-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Aug 9, 2019

k8s-ci-robot assigned neolit123 Aug 9, 2019

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 9, 2019

johnSchnake reviewed Aug 9, 2019

View reviewed changes

k8s-ci-robot requested a review from oomichi August 17, 2019 00:24

Dump the stacktrace while an error occurs

9a2ccc2

Signed-off-by: Jiatong Wang <wangjiatong@vmware.com>

jiatongw force-pushed the e2e/framework/printstack branch from a9ce198 to 9a2ccc2 Compare August 21, 2019 18:29

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 21, 2019

k8s-ci-robot added lgtm "Looks good to me", indicates that a PR is ready to be merged. and removed do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. labels Aug 21, 2019

k8s-ci-robot merged commit 68d6ec9 into kubernetes:master Aug 22, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[e2e] Dump the stacktrace while an error occurs #80979

[e2e] Dump the stacktrace while an error occurs #80979

jiatongw commented Aug 5, 2019

jiatongw commented Aug 5, 2019

jiatongw commented Aug 5, 2019

jiatongw Aug 5, 2019

jiatongw commented Aug 5, 2019

timothysc left a comment

k8s-ci-robot commented Aug 5, 2019

johnSchnake Aug 5, 2019

jiatongw Aug 5, 2019 •

edited

jiatongw Aug 5, 2019

johnSchnake Aug 5, 2019

jiatongw Aug 5, 2019

johnSchnake Aug 5, 2019

jiatongw Aug 5, 2019

johnSchnake Aug 5, 2019

jiatongw Aug 5, 2019

timothysc commented Aug 5, 2019

jiatongw commented Aug 5, 2019

neolit123 left a comment •

edited

neolit123 Aug 6, 2019

jiatongw Aug 7, 2019 •

edited

jiatongw Aug 7, 2019

neolit123 Aug 7, 2019

jiatongw Aug 9, 2019

neolit123 commented Aug 7, 2019

jiatongw commented Aug 7, 2019

neolit123 left a comment

jiatongw commented Aug 9, 2019

johnSchnake Aug 9, 2019

jiatongw Aug 14, 2019

johnSchnake Aug 19, 2019

jiatongw Aug 21, 2019

oomichi commented Aug 17, 2019

johnSchnake commented Aug 21, 2019

[e2e] Dump the stacktrace while an error occurs #80979

[e2e] Dump the stacktrace while an error occurs #80979

Conversation

jiatongw commented Aug 5, 2019

jiatongw commented Aug 5, 2019

jiatongw commented Aug 5, 2019

Choose a reason for hiding this comment

jiatongw commented Aug 5, 2019

timothysc left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented Aug 5, 2019

Choose a reason for hiding this comment

jiatongw Aug 5, 2019 • edited

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

timothysc commented Aug 5, 2019

jiatongw commented Aug 5, 2019

neolit123 left a comment • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jiatongw Aug 7, 2019 • edited

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

neolit123 commented Aug 7, 2019

jiatongw commented Aug 7, 2019

neolit123 left a comment

Choose a reason for hiding this comment

jiatongw commented Aug 9, 2019

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

oomichi commented Aug 17, 2019

johnSchnake commented Aug 21, 2019

jiatongw Aug 5, 2019 •

edited

neolit123 left a comment •

edited

jiatongw Aug 7, 2019 •

edited