apimachinery & apiserver: use stacktrace in the stdlib #75853

roycaihw · 2019-03-29T00:40:10Z

use runtime.Stack() in the stdlib to log stack trace instead of using customized code, so that third party lib can parse the panic (like panicparse)

e.g. if we have a panic here, with the change, the tool is able to parse all three goroutines

without the change, only the first goroutine (finishRequest) gets parsed. The second goroutine (timeoutHandler) is missed because we drop a trailing newline in the one goroutine before. The third goroutine (HandleCrash) is missed because getCaller() is non-standard which only contains filename + line number.

Does this PR introduce a user-facing change?:

Use stdlib to log stack trace when a panic occurs

/cc @logicalhan @sttts

liggitt · 2019-03-29T02:39:00Z

I think the size limit was to prevent excessively large logs (stdlib http server panic handling does the same thing)

I don't know why the custom caller code was added initially. @smarterclayton, do you know?

logicalhan

I think the size limit was to prevent excessively large logs (stdlib http server panic handling does the same thing)

That makes sense. Maybe we should add a comment if we revert to that behavior?

Personally I like this change. I find the callers thing quite odd.

logicalhan · 2019-03-29T00:43:58Z

staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go

@@ -92,23 +92,22 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}

-	errCh := make(chan interface{})
+	// resultCh is used as both errCh and stopCh


Nice, I like the rename. It makes more sense.

logicalhan · 2019-03-29T03:26:59Z

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go

@@ -62,27 +63,14 @@ func HandleCrash(additionalHandlers ...func(interface{})) {

 // logPanic logs the caller tree when a panic occurs.
 func logPanic(r interface{}) {
-	callers := getCallers(r)
+	callers := debug.Stack()


probably better to rename this to stacktrace?

logicalhan · 2019-03-29T03:28:05Z

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go

@@ -155,10 +143,10 @@ func GetCaller() string {
 // handlers to handle errors and panics the same way.
 func RecoverFromPanic(err *error) {
 	if r := recover(); r != nil {
-		callers := getCallers(r)
+		callers := debug.Stack()


smarterclayton · 2019-03-29T04:30:51Z

I think this code was added before Go had an easy way to get a stack dump. There may have been a security concern too (avoiding showing some portions of the stack). But it’s been too long.

roycaihw · 2019-03-29T17:59:40Z

2012: runtime/debug.Stack was deprecated (golang/go#4070, golang/go@e49a183)
2012: stdlib http server switched from runtime/debug.Stack to runtime.Stack with 4KB buf size (golang/go#4060, golang/go@dd43bf8)
2014: the http server increased buf size from 4KB to 64KB golang/go@645a341
2015: runtime/debug.Stack was re-implemented and un-deprecated golang/go@2d697b2
2017-2019: some conversation comparing the two APIs golang/go#3845 (comment)

I can go with manually allocating buf size if excessively large log is a concern. Will update the PR soon

roycaihw · 2019-04-01T18:15:54Z

updated. I'm working on adding a test to capture what's printed in klog

logicalhan

Thanks for adding the test!

/lgtm

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go

logicalhan · 2019-04-01T23:46:16Z

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go

-		callers := getCallers(r)
+		// Same as stdlib http server code. Manually allocate stack trace buffer size
+		// to prevent excessively large logs
+		const size = 64 << 10


I wonder if it would be worth extracting this logic somewhere, since we do the same thing in handlers/rest.go. Probably not though..

I agree. I'm not sure on this

on one hand, I'd imagine extracting this logic would result in one more function call in the call stack

on the other hand, I guess there are more places in our code base need this logic (I was about to add the logic here until I saw #73137 (comment))

sttts · 2019-04-02T07:53:34Z

Looks good.

Can you post the difference in output from before and after this PR?

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go

roycaihw · 2019-04-02T19:42:31Z

Can you post the difference in output from before and after this PR?

@sttts https://gist.github.com/roycaihw/b0977279000fb3f3048c3b77df89bec5

to reproduce: include this commit, bring up apiserver and look for the last occurrence of "Observed a panic" in apiserver log

roycaihw · 2019-04-03T00:52:38Z

/retest

sttts · 2019-04-03T07:31:08Z

@roycaihw do I read the gist correctly that we print all 3249 go routine stack traces now, while only one before?

roycaihw · 2019-04-03T17:10:52Z

@sttts we print stacktraces for 3 goroutines in both cases

after:

goroutine 3247 handlers.finishRequest
goroutine 3246 filters.(*timeoutHandler).ServeHTTP
goroutine 3277 runtime.logPanic

before:

goroutine 3277 handlers.finishRequest (without trailing newline)
goroutine 3276 filters.(*timeoutHandler).ServeHTTP
filename+line# (runtime.logPanic)

/retest

roycaihw · 2019-04-05T18:21:23Z

@liggitt could you approve this PR?

/retest

liggitt · 2019-04-05T18:33:09Z

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go

+	if match, _ := regexp.MatchString(`logPanic(.*)`, lines[2]); !match {
+		t.Errorf("mismatch symbolized function name: %s", lines[2])
+	}
+	if match, _ := regexp.MatchString(`runtime\.go:69 \+0x`, lines[3]); !match {


this seems like a fragile test... is this format and line number stable across releases?

same question for the [running] format, etc

line #: it's fragile. I meant to have people update the number when changing our runtime.go, but it's not necessary

[running]: it comes from one of the statuses. Should be stable in this test

updated both to use regexp. The rest of the test should be stable enough

also added documentation about if golang stdlib changes its format

liggitt · 2019-04-05T19:10:37Z

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go

+
+// captureStderr redirects stderr to result string, and then restore stderr from backup
+func captureStderr(f func()) (string, error) {
+	bak := os.Stderr


defer func(){ os.Stderr = bak }()

updated

tried to defer closing the writable file before, and it behaved weirdly (stuck on flushing the buffer?)

liggitt · 2019-04-05T22:38:22Z

/lgtm
/approve
/retest

k8s-ci-robot · 2019-04-05T22:38:29Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: liggitt, roycaihw

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:

~~staging/src/k8s.io/apimachinery/pkg/OWNERS~~ [liggitt]
~~staging/src/k8s.io/apiserver/OWNERS~~ [liggitt]

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

lavalamp · 2019-09-10T18:07:49Z

I think this code was added before Go had an easy way to get a stack dump.

Yeah, I'm pretty sure I added this code, for this reason.

k8s-ci-robot requested a review from logicalhan March 29, 2019 00:40

k8s-ci-robot added the release-note Denotes a PR that will be considered when it comes time to generate release notes. label Mar 29, 2019

k8s-ci-robot requested a review from sttts March 29, 2019 00:40

logicalhan reviewed Mar 29, 2019

View reviewed changes

document the usage of errCh

5809b6a

roycaihw added 2 commits April 1, 2019 10:58

use stdlib runtime.Stack instead of customized code

5c81571

remove TrimSuffix and document buffer size

0e61b77

roycaihw force-pushed the fix/use-standard-stacktrace branch from 943a02b to 0e61b77 Compare April 1, 2019 18:11

k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Apr 1, 2019

k8s-ci-robot assigned logicalhan Apr 1, 2019

logicalhan approved these changes Apr 1, 2019

View reviewed changes

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

roycaihw force-pushed the fix/use-standard-stacktrace branch from 739be66 to 826cb90 Compare April 1, 2019 23:59

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

roycaihw force-pushed the fix/use-standard-stacktrace branch from 826cb90 to d5ca73a Compare April 2, 2019 00:53

sttts added the priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. label Apr 2, 2019

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

sttts added kind/cleanup Categorizes issue or PR as related to cleaning up code, process, or technical debt. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Apr 2, 2019

k8s-ci-robot removed the needs-kind Indicates a PR lacks a `kind/foo` label and requires one. label Apr 2, 2019

roycaihw commented Apr 2, 2019

View reviewed changes

staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go Outdated Show resolved Hide resolved

roycaihw force-pushed the fix/use-standard-stacktrace branch from d5ca73a to a2c59f5 Compare April 2, 2019 19:40

liggitt reviewed Apr 5, 2019

View reviewed changes

roycaihw force-pushed the fix/use-standard-stacktrace branch from a2c59f5 to ca8fcfc Compare April 5, 2019 19:37

test panic log text

999a02c

roycaihw force-pushed the fix/use-standard-stacktrace branch from ca8fcfc to 999a02c Compare April 5, 2019 19:50

k8s-ci-robot assigned liggitt Apr 5, 2019

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

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

k8s-ci-robot merged commit f8d0b21 into kubernetes:master Apr 6, 2019

wojtek-t mentioned this pull request Apr 17, 2019

API call latency regression #76579

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

apimachinery & apiserver: use stacktrace in the stdlib #75853

apimachinery & apiserver: use stacktrace in the stdlib #75853

roycaihw commented Mar 29, 2019 •

edited

Loading

liggitt commented Mar 29, 2019

logicalhan left a comment

logicalhan Mar 29, 2019

logicalhan Mar 29, 2019

logicalhan Mar 29, 2019

smarterclayton commented Mar 29, 2019

roycaihw commented Mar 29, 2019

roycaihw commented Apr 1, 2019

logicalhan left a comment

logicalhan Apr 1, 2019

roycaihw Apr 2, 2019 •

edited

Loading

sttts commented Apr 2, 2019 •

edited

Loading

roycaihw commented Apr 2, 2019 •

edited

Loading

roycaihw commented Apr 3, 2019

sttts commented Apr 3, 2019

roycaihw commented Apr 3, 2019

roycaihw commented Apr 5, 2019

liggitt Apr 5, 2019

liggitt Apr 5, 2019

roycaihw Apr 5, 2019

liggitt Apr 5, 2019 •

edited

Loading

roycaihw Apr 5, 2019

liggitt commented Apr 5, 2019

k8s-ci-robot commented Apr 5, 2019

lavalamp commented Sep 10, 2019

apimachinery & apiserver: use stacktrace in the stdlib #75853

apimachinery & apiserver: use stacktrace in the stdlib #75853

Conversation

roycaihw commented Mar 29, 2019 • edited Loading

liggitt commented Mar 29, 2019

logicalhan 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

smarterclayton commented Mar 29, 2019

roycaihw commented Mar 29, 2019

roycaihw commented Apr 1, 2019

logicalhan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

roycaihw Apr 2, 2019 • edited Loading

Choose a reason for hiding this comment

sttts commented Apr 2, 2019 • edited Loading

roycaihw commented Apr 2, 2019 • edited Loading

roycaihw commented Apr 3, 2019

sttts commented Apr 3, 2019

roycaihw commented Apr 3, 2019

roycaihw commented Apr 5, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

liggitt Apr 5, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

liggitt commented Apr 5, 2019

k8s-ci-robot commented Apr 5, 2019

lavalamp commented Sep 10, 2019

roycaihw commented Mar 29, 2019 •

edited

Loading

roycaihw Apr 2, 2019 •

edited

Loading

sttts commented Apr 2, 2019 •

edited

Loading

roycaihw commented Apr 2, 2019 •

edited

Loading

liggitt Apr 5, 2019 •

edited

Loading