From e43e5e2e4547c7cfb50190d67556352ef0aee9e8 Mon Sep 17 00:00:00 2001 From: "Dr. Stefan Schimanski" Date: Thu, 15 Nov 2018 09:26:02 +0100 Subject: [PATCH 1/2] apiserver: in timeout_test separate out handler --- .../pkg/server/filters/timeout_test.go | 30 +++++++++++-------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go index 28403f9350..905566ad70 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go @@ -50,6 +50,18 @@ func (r *recorder) Count() int { return r.count } +func newHandler(responseCh <-chan string, panicCh <-chan struct{}, writeErrCh chan<- error) http.HandlerFunc { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + select { + case resp := <-responseCh: + _, err := w.Write([]byte(resp)) + writeErrCh <- err + case <-panicCh: + panic("inner handler panics") + } + }) +} + func TestTimeout(t *testing.T) { origReallyCrash := runtime.ReallyCrash runtime.ReallyCrash = false @@ -57,7 +69,7 @@ func TestTimeout(t *testing.T) { runtime.ReallyCrash = origReallyCrash }() - sendResponse := make(chan struct{}, 1) + sendResponse := make(chan string, 1) doPanic := make(chan struct{}, 1) writeErrors := make(chan error, 1) timeout := make(chan time.Time, 1) @@ -65,23 +77,15 @@ func TestTimeout(t *testing.T) { timeoutErr := apierrors.NewServerTimeout(schema.GroupResource{Group: "foo", Resource: "bar"}, "get", 0) record := &recorder{} - ts := httptest.NewServer(WithPanicRecovery(WithTimeout(http.HandlerFunc( - func(w http.ResponseWriter, r *http.Request) { - select { - case <-sendResponse: - _, err := w.Write([]byte(resp)) - writeErrors <- err - case <-doPanic: - panic("inner handler panics") - } - }), + handler := newHandler(sendResponse, doPanic, writeErrors) + ts := httptest.NewServer(WithPanicRecovery(WithTimeout(handler, func(req *http.Request) (*http.Request, <-chan time.Time, func(), *apierrors.StatusError) { return req, timeout, record.Record, timeoutErr }))) defer ts.Close() // No timeouts - sendResponse <- struct{}{} + sendResponse <- resp res, err := http.Get(ts.URL) if err != nil { t.Fatal(err) @@ -122,7 +126,7 @@ func TestTimeout(t *testing.T) { } // Now try to send a response - sendResponse <- struct{}{} + sendResponse <- resp if err := <-writeErrors; err != http.ErrHandlerTimeout { t.Errorf("got Write error of %v; expected %v", err, http.ErrHandlerTimeout) } From 96fd0482f41ff34ef7d9b7de07ded38152a35141 Mon Sep 17 00:00:00 2001 From: "Dr. Stefan Schimanski" Date: Thu, 15 Nov 2018 09:56:49 +0100 Subject: [PATCH 2/2] apiserver: preserve stack trace in handler panic beyond timeout handler --- .../apimachinery/pkg/util/runtime/runtime.go | 6 ++++- .../apiserver/pkg/server/filters/timeout.go | 14 +++++++++--- .../pkg/server/filters/timeout_test.go | 22 ++++++++++++++++--- .../apiserver/pkg/server/filters/wrap.go | 11 +++++++--- 4 files changed, 43 insertions(+), 10 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 3512e68e16..8e34f92613 100644 --- a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go +++ b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go @@ -63,7 +63,11 @@ func HandleCrash(additionalHandlers ...func(interface{})) { // logPanic logs the caller tree when a panic occurs. func logPanic(r interface{}) { callers := getCallers(r) - klog.Errorf("Observed a panic: %#v (%v)\n%v", r, r, callers) + if _, ok := r.(string); ok { + klog.Errorf("Observed a panic: %s\n%v", r, callers) + } else { + klog.Errorf("Observed a panic: %#v (%v)\n%v", r, r, callers) + } } func getCallers(r interface{}) string { 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 7d37ed05a3..adb179f823 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go @@ -23,6 +23,7 @@ import ( "fmt" "net" "net/http" + "runtime" "sync" "time" @@ -91,16 +92,23 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } - result := make(chan interface{}) + errCh := make(chan interface{}) tw := newTimeoutWriter(w) go func() { defer func() { - result <- recover() + err := recover() + if err != nil { + const size = 64 << 10 + buf := make([]byte, size) + buf = buf[:runtime.Stack(buf, false)] + err = fmt.Sprintf("%v\n%s", err, buf) + } + errCh <- err }() t.handler.ServeHTTP(tw, r) }() select { - case err := <-result: + case err := <-errCh: if err != nil { panic(err) } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go index 905566ad70..26f571d08a 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go @@ -18,10 +18,12 @@ package filters import ( "encoding/json" + "fmt" "io/ioutil" "net/http" "net/http/httptest" "reflect" + "strings" "sync" "testing" "time" @@ -72,16 +74,21 @@ func TestTimeout(t *testing.T) { sendResponse := make(chan string, 1) doPanic := make(chan struct{}, 1) writeErrors := make(chan error, 1) + gotPanic := make(chan interface{}, 1) timeout := make(chan time.Time, 1) resp := "test response" timeoutErr := apierrors.NewServerTimeout(schema.GroupResource{Group: "foo", Resource: "bar"}, "get", 0) record := &recorder{} handler := newHandler(sendResponse, doPanic, writeErrors) - ts := httptest.NewServer(WithPanicRecovery(WithTimeout(handler, - func(req *http.Request) (*http.Request, <-chan time.Time, func(), *apierrors.StatusError) { + ts := httptest.NewServer(withPanicRecovery( + WithTimeout(handler, func(req *http.Request) (*http.Request, <-chan time.Time, func(), *apierrors.StatusError) { return req, timeout, record.Record, timeoutErr - }))) + }), func(w http.ResponseWriter, req *http.Request, err interface{}) { + gotPanic <- err + http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError) + }), + ) defer ts.Close() // No timeouts @@ -140,4 +147,13 @@ func TestTimeout(t *testing.T) { if res.StatusCode != http.StatusInternalServerError { t.Errorf("got res.StatusCode %d; expected %d due to panic", res.StatusCode, http.StatusInternalServerError) } + select { + case err := <-gotPanic: + msg := fmt.Sprintf("%v", err) + if !strings.Contains(msg, "newHandler") { + t.Errorf("expected line with root cause panic in the stack trace, but didn't: %v", err) + } + case <-time.After(30 * time.Second): + t.Fatalf("expected to see a handler panic, but didn't") + } } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go index 46842c6973..0a75845611 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go @@ -18,7 +18,6 @@ package filters import ( "net/http" - "runtime/debug" "k8s.io/klog" @@ -28,10 +27,16 @@ import ( // WithPanicRecovery wraps an http Handler to recover and log panics. func WithPanicRecovery(handler http.Handler) http.Handler { + return withPanicRecovery(handler, func(w http.ResponseWriter, req *http.Request, err interface{}) { + http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError) + klog.Errorf("apiserver panic'd on %v %v", req.Method, req.RequestURI) + }) +} + +func withPanicRecovery(handler http.Handler, crashHandler func(http.ResponseWriter, *http.Request, interface{})) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { defer runtime.HandleCrash(func(err interface{}) { - http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError) - klog.Errorf("apiserver panic'd on %v %v: %v\n%s\n", req.Method, req.RequestURI, err, debug.Stack()) + crashHandler(w, req, err) }) logger := httplog.NewLogged(req, &w)