From 43415294a72d13a6d685ec0e2ecb274fada7587c Mon Sep 17 00:00:00 2001 From: Jordan Liggitt Date: Wed, 11 Sep 2019 11:16:31 -0400 Subject: [PATCH] Propagate and honor http.ErrAbortHandler --- .../apimachinery/pkg/util/runtime/runtime.go | 11 +++++++- .../pkg/util/runtime/runtime_test.go | 19 +++++++++++++ .../apiserver/pkg/endpoints/handlers/rest.go | 15 ++++++---- .../pkg/endpoints/handlers/rest_test.go | 17 +++++++++++ .../apiserver/pkg/server/filters/timeout.go | 3 +- .../pkg/server/filters/timeout_test.go | 28 +++++++++++++++---- .../apiserver/pkg/server/filters/wrap.go | 9 +++++- 7 files changed, 88 insertions(+), 14 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 c7348129ae8..1428443f544 100644 --- a/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go +++ b/staging/src/k8s.io/apimachinery/pkg/util/runtime/runtime.go @@ -18,6 +18,7 @@ package runtime import ( "fmt" + "net/http" "runtime" "sync" "time" @@ -56,8 +57,16 @@ func HandleCrash(additionalHandlers ...func(interface{})) { } } -// logPanic logs the caller tree when a panic occurs. +// logPanic logs the caller tree when a panic occurs (except in the special case of http.ErrAbortHandler). func logPanic(r interface{}) { + if r == http.ErrAbortHandler { + // honor the http.ErrAbortHandler sentinel panic value: + // ErrAbortHandler is a sentinel panic value to abort a handler. + // While any panic from ServeHTTP aborts the response to the client, + // panicking with ErrAbortHandler also suppresses logging of a stack trace to the server's error log. + return + } + // Same as stdlib http server code. Manually allocate stack trace buffer size // to prevent excessively large logs const size = 64 << 10 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 8ae21db4109..2368a513b91 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 @@ -20,6 +20,7 @@ import ( "bytes" "fmt" "io" + "net/http" "os" "regexp" "strings" @@ -114,6 +115,24 @@ func TestHandleCrashLog(t *testing.T) { } } +func TestHandleCrashLogSilenceHTTPErrAbortHandler(t *testing.T) { + log, err := captureStderr(func() { + defer func() { + if r := recover(); r != http.ErrAbortHandler { + t.Fatalf("expected to recover from http.ErrAbortHandler") + } + }() + defer HandleCrash() + panic(http.ErrAbortHandler) + }) + if err != nil { + t.Fatalf("%v", err) + } + if len(log) > 0 { + t.Fatalf("expected no stderr log, got: %s", log) + } +} + // captureStderr redirects stderr to result string, and then restore stderr from backup func captureStderr(f func()) (string, error) { r, w, err := os.Pipe() 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 75764597f49..bc47a72ee72 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go @@ -220,12 +220,15 @@ 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 = fmt.Sprintf("%v\n%s", panicReason, buf) + // do not wrap the sentinel ErrAbortHandler panic value + if panicReason != http.ErrAbortHandler { + // 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 = fmt.Sprintf("%v\n%s", panicReason, buf) + } // Propagate to parent goroutine panicCh <- panicReason } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest_test.go index 924990a8c2a..ca8c769e90b 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest_test.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest_test.go @@ -849,6 +849,8 @@ func TestFinishRequest(t *testing.T) { expectedObj runtime.Object expectedErr error expectedPanic string + + expectedPanicObj interface{} }{ { name: "Expected obj is returned", @@ -906,6 +908,17 @@ func TestFinishRequest(t *testing.T) { expectedErr: nil, expectedPanic: "rest_test.go", }, + { + name: "http.ErrAbortHandler panic is propagated without wrapping with stack", + timeout: time.Second, + fn: func() (runtime.Object, error) { + panic(http.ErrAbortHandler) + }, + expectedObj: nil, + expectedErr: nil, + expectedPanic: http.ErrAbortHandler.Error(), + expectedPanicObj: http.ErrAbortHandler, + }, } for i, tc := range testcases { t.Run(tc.name, func(t *testing.T) { @@ -919,6 +932,10 @@ func TestFinishRequest(t *testing.T) { case r != nil && len(tc.expectedPanic) > 0 && !strings.Contains(fmt.Sprintf("%v", r), tc.expectedPanic): t.Errorf("expected panic containing '%s', got '%v'", tc.expectedPanic, r) } + + if tc.expectedPanicObj != nil && !reflect.DeepEqual(tc.expectedPanicObj, r) { + t.Errorf("expected panic obj %#v, got %#v", tc.expectedPanicObj, r) + } }() obj, err := finishRequest(tc.timeout, tc.fn) if (err == nil && tc.expectedErr != nil) || (err != nil && tc.expectedErr == nil) || (err != nil && tc.expectedErr != nil && err.Error() != tc.expectedErr.Error()) { 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 e79da50bf20..559aca7e2b7 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go @@ -98,7 +98,8 @@ func (t *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { go func() { defer func() { err := recover() - if err != nil { + // do not wrap the sentinel ErrAbortHandler panic value + if err != nil && err != http.ErrAbortHandler { // Same as stdlib http server code. Manually allocate stack // trace buffer size to prevent excessively large logs const size = 64 << 10 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 26f571d08af..4ad8717c018 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 @@ -52,14 +52,14 @@ func (r *recorder) Count() int { return r.count } -func newHandler(responseCh <-chan string, panicCh <-chan struct{}, writeErrCh chan<- error) http.HandlerFunc { +func newHandler(responseCh <-chan string, panicCh <-chan interface{}, 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") + case panicReason := <-panicCh: + panic(panicReason) } }) } @@ -72,7 +72,7 @@ func TestTimeout(t *testing.T) { }() sendResponse := make(chan string, 1) - doPanic := make(chan struct{}, 1) + doPanic := make(chan interface{}, 1) writeErrors := make(chan error, 1) gotPanic := make(chan interface{}, 1) timeout := make(chan time.Time, 1) @@ -139,7 +139,7 @@ func TestTimeout(t *testing.T) { } // Panics - doPanic <- struct{}{} + doPanic <- "inner handler panics" res, err = http.Get(ts.URL) if err != nil { t.Fatal(err) @@ -156,4 +156,22 @@ func TestTimeout(t *testing.T) { case <-time.After(30 * time.Second): t.Fatalf("expected to see a handler panic, but didn't") } + + // Panics with http.ErrAbortHandler + doPanic <- http.ErrAbortHandler + res, err = http.Get(ts.URL) + if err != nil { + t.Fatal(err) + } + if res.StatusCode != http.StatusInternalServerError { + t.Errorf("got res.StatusCode %d; expected %d due to panic", res.StatusCode, http.StatusInternalServerError) + } + select { + case err := <-gotPanic: + if err != http.ErrAbortHandler { + t.Errorf("expected unwrapped http.ErrAbortHandler, got %#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 d99308861c8..96bebdbd600 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go @@ -25,9 +25,16 @@ import ( "k8s.io/apiserver/pkg/server/httplog" ) -// WithPanicRecovery wraps an http Handler to recover and log panics. +// WithPanicRecovery wraps an http Handler to recover and log panics (except in the special case of http.ErrAbortHandler panics, which suppress logging). func WithPanicRecovery(handler http.Handler) http.Handler { return withPanicRecovery(handler, func(w http.ResponseWriter, req *http.Request, err interface{}) { + if err == http.ErrAbortHandler { + // honor the http.ErrAbortHandler sentinel panic value: + // ErrAbortHandler is a sentinel panic value to abort a handler. + // While any panic from ServeHTTP aborts the response to the client, + // panicking with ErrAbortHandler also suppresses logging of a stack trace to the server's error log. + return + } 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) })