Merge pull request #71067 from sttts/sttts-handler-panic

apiserver: preserve stack trace in handler panic beyond timeout handler

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 {

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)
 		}

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"
@@ -50,6 +52,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,31 +71,28 @@ 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)
+	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{}
 
-	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")
-			}
-		}),
-		func(req *http.Request) (*http.Request, <-chan time.Time, func(), *apierrors.StatusError) {
+	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
-		})))
+		}), 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
-	sendResponse <- struct{}{}
+	sendResponse <- resp
 	res, err := http.Get(ts.URL)
 	if err != nil {
 		t.Fatal(err)
@@ -122,7 +133,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)
 	}
@@ -136,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")
+	}
 }

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)