From 5809b6a4282f7ce58e0d815d9326289a8ee7ddb6 Mon Sep 17 00:00:00 2001 From: Haowei Cai Date: Thu, 28 Mar 2019 16:55:03 -0700 Subject: [PATCH 1/4] document the usage of errCh --- .../src/k8s.io/apiserver/pkg/server/filters/timeout.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go index 56cd8a4ce0..4ade375a2f 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go @@ -92,7 +92,8 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } - errCh := make(chan interface{}) + // resultCh is used as both errCh and stopCh + resultCh := make(chan interface{}) tw := newTimeoutWriter(w) go func() { defer func() { @@ -103,12 +104,13 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { buf = buf[:runtime.Stack(buf, false)] err = fmt.Sprintf("%v\n%s", err, buf) } - errCh <- err + resultCh <- err }() t.handler.ServeHTTP(tw, r) }() select { - case err := <-errCh: + case err := <-resultCh: + // panic if error occurs; stop otherwise if err != nil { panic(err) } From 5c81571b016396bed66a6ff504a7481090cf3253 Mon Sep 17 00:00:00 2001 From: Haowei Cai Date: Mon, 1 Apr 2019 10:58:57 -0700 Subject: [PATCH 2/4] use stdlib runtime.Stack instead of customized code --- .../apimachinery/pkg/util/runtime/runtime.go | 33 ++++++++----------- 1 file changed, 14 insertions(+), 19 deletions(-) diff --git a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go index 8e34f92613..3c886f46c3 100644 --- a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go +++ b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go @@ -62,27 +62,18 @@ func HandleCrash(additionalHandlers ...func(interface{})) { // logPanic logs the caller tree when a panic occurs. func logPanic(r interface{}) { - callers := getCallers(r) + // Same as stdlib http server code. Manually allocate stack trace buffer size + // to prevent excessively large logs + const size = 64 << 10 + stacktrace := make([]byte, size) + stacktrace = stacktrace[:runtime.Stack(stacktrace, false)] if _, ok := r.(string); ok { - klog.Errorf("Observed a panic: %s\n%v", r, callers) + klog.Errorf("Observed a panic: %s\n%s", r, stacktrace) } else { - klog.Errorf("Observed a panic: %#v (%v)\n%v", r, r, callers) + klog.Errorf("Observed a panic: %#v (%v)\n%s", r, r, stacktrace) } } -func getCallers(r interface{}) string { - callers := "" - for i := 0; true; i++ { - _, file, line, ok := runtime.Caller(i) - if !ok { - break - } - callers = callers + fmt.Sprintf("%v:%v\n", file, line) - } - - return callers -} - // ErrorHandlers is a list of functions which will be invoked when an unreturnable // error occurs. // TODO(lavalamp): for testability, this and the below HandleError function @@ -155,13 +146,17 @@ func GetCaller() string { // handlers to handle errors and panics the same way. func RecoverFromPanic(err *error) { if r := recover(); r != nil { - callers := getCallers(r) + // Same as stdlib http server code. Manually allocate stack trace buffer size + // to prevent excessively large logs + const size = 64 << 10 + stacktrace := make([]byte, size) + stacktrace = stacktrace[:runtime.Stack(stacktrace, false)] *err = fmt.Errorf( - "recovered from panic %q. (err=%v) Call stack:\n%v", + "recovered from panic %q. (err=%v) Call stack:\n%s", r, *err, - callers) + stacktrace) } } From 0e61b77826f23cbf835002a9eef5722bb1cfdf53 Mon Sep 17 00:00:00 2001 From: Haowei Cai Date: Mon, 1 Apr 2019 11:02:39 -0700 Subject: [PATCH 3/4] remove TrimSuffix and document buffer size --- staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go | 5 +++-- staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go | 2 ++ 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go index c184ce5f99..eb27fbf123 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go @@ -25,7 +25,6 @@ import ( "net/http" "net/url" goruntime "runtime" - "strings" "time" "k8s.io/apimachinery/pkg/api/errors" @@ -197,10 +196,12 @@ func finishRequest(timeout time.Duration, fn resultFunc) (result runtime.Object, defer func() { panicReason := recover() if panicReason != nil { + // Same as stdlib http server code. Manually allocate stack + // trace buffer size to prevent excessively large logs const size = 64 << 10 buf := make([]byte, size) buf = buf[:goruntime.Stack(buf, false)] - panicReason = strings.TrimSuffix(fmt.Sprintf("%v\n%s", panicReason, string(buf)), "\n") + panicReason = fmt.Sprintf("%v\n%s", panicReason, buf) // Propagate to parent goroutine panicCh <- panicReason } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go index 4ade375a2f..e79da50bf2 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go @@ -99,6 +99,8 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { defer func() { err := recover() if err != nil { + // Same as stdlib http server code. Manually allocate stack + // trace buffer size to prevent excessively large logs const size = 64 << 10 buf := make([]byte, size) buf = buf[:runtime.Stack(buf, false)] From 999a02ceb6476fa2dd344ce37d820884ae4674ce Mon Sep 17 00:00:00 2001 From: Haowei Cai Date: Mon, 1 Apr 2019 15:43:34 -0700 Subject: [PATCH 4/4] test panic log text --- .../pkg/util/runtime/runtime_test.go | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) diff --git a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go index 9dff17ea53..8ae21db410 100644 --- a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go +++ b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime_test.go @@ -17,7 +17,12 @@ limitations under the License. package runtime import ( + "bytes" "fmt" + "io" + "os" + "regexp" + "strings" "testing" ) @@ -69,3 +74,66 @@ func TestCustomHandleError(t *testing.T) { t.Errorf("did not receive custom handler") } } + +func TestHandleCrashLog(t *testing.T) { + log, err := captureStderr(func() { + defer func() { + if r := recover(); r == nil { + t.Fatalf("expected a panic to recover from") + } + }() + defer HandleCrash() + panic("test panic") + }) + if err != nil { + t.Fatalf("%v", err) + } + // Example log: + // + // ...] Observed a panic: test panic + // goroutine 6 [running]: + // command-line-arguments.logPanic(0x..., 0x...) + // .../src/k8s.io/kubernetes/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go:69 +0x... + lines := strings.Split(log, "\n") + if len(lines) < 4 { + t.Fatalf("panic log should have 1 line of message, 1 line per goroutine and 2 lines per function call") + } + if match, _ := regexp.MatchString("Observed a panic: test panic", lines[0]); !match { + t.Errorf("mismatch panic message: %s", lines[0]) + } + // The following regexp's verify that Kubernetes panic log matches Golang stdlib + // stacktrace pattern. We need to update these regexp's if stdlib changes its pattern. + if match, _ := regexp.MatchString(`goroutine [0-9]+ \[.+\]:`, lines[1]); !match { + t.Errorf("mismatch goroutine: %s", lines[1]) + } + if match, _ := regexp.MatchString(`logPanic(.*)`, lines[2]); !match { + t.Errorf("mismatch symbolized function name: %s", lines[2]) + } + if match, _ := regexp.MatchString(`runtime\.go:[0-9]+ \+0x`, lines[3]); !match { + t.Errorf("mismatch file/line/offset information: %s", lines[3]) + } +} + +// captureStderr redirects stderr to result string, and then restore stderr from backup +func captureStderr(f func()) (string, error) { + r, w, err := os.Pipe() + if err != nil { + return "", err + } + bak := os.Stderr + os.Stderr = w + defer func() { os.Stderr = bak }() + + resultCh := make(chan string) + // copy the output in a separate goroutine so printing can't block indefinitely + go func() { + var buf bytes.Buffer + io.Copy(&buf, r) + resultCh <- buf.String() + }() + + f() + w.Close() + + return <-resultCh, nil +}