Automated cherry pick of #71067: apiserver: in timeout_test separate out handler #71076: apiserver: propagate panics from REST handlers correctly

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)
-	glog.Errorf("Observed a panic: %#v (%v)\n%v", r, r, callers)
+	if _, ok := r.(string); ok {
+		glog.Errorf("Observed a panic: %s\n%v", r, callers)
+	} else {
+		glog.Errorf("Observed a panic: %#v (%v)\n%v", r, r, callers)
+	}
 }
 
 func getCallers(r interface{}) string {

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest.go

@@ -21,6 +21,8 @@ import (
 	"fmt"
 	"io/ioutil"
 	"net/http"
+	goruntime "runtime"
+	"strings"
 	"time"
 
 	"github.com/golang/glog"
@@ -31,7 +33,6 @@ import (
 	metav1beta1 "k8s.io/apimachinery/pkg/apis/meta/v1beta1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
-	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/endpoints/handlers/responsewriters"
 	"k8s.io/apiserver/pkg/endpoints/metrics"
@@ -174,10 +175,17 @@ func finishRequest(timeout time.Duration, fn resultFunc) (result runtime.Object,
 	panicCh := make(chan interface{}, 1)
 	go func() {
 		// panics don't cross goroutine boundaries, so we have to handle ourselves
-		defer utilruntime.HandleCrash(func(panicReason interface{}) {
+		defer func() {
+			panicReason := recover()
+			if panicReason != nil {
+				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")
+			}
 			// Propagate to parent goroutine
 			panicCh <- panicReason
-		})
+		}()
 
 		if result, err := fn(); err != nil {
 			errCh <- err

staging/src/k8s.io/apiserver/pkg/endpoints/handlers/rest_test.go

@@ -21,6 +21,7 @@ import (
 	"fmt"
 	"net/http"
 	"reflect"
+	"strings"
 	"testing"
 	"time"
 
@@ -739,13 +740,15 @@ func TestFinishRequest(t *testing.T) {
 	successStatusObj := &metav1.Status{Status: metav1.StatusSuccess, Message: "success message"}
 	errorStatusObj := &metav1.Status{Status: metav1.StatusFailure, Message: "error message"}
 	testcases := []struct {
-		timeout     time.Duration
-		fn          resultFunc
-		expectedObj runtime.Object
-		expectedErr error
+		name          string
+		timeout       time.Duration
+		fn            resultFunc
+		expectedObj   runtime.Object
+		expectedErr   error
+		expectedPanic string
 	}{
 		{
-			// Expected obj is returned.
+			name:    "Expected obj is returned",
 			timeout: time.Second,
 			fn: func() (runtime.Object, error) {
 				return exampleObj, nil
@@ -754,7 +757,7 @@ func TestFinishRequest(t *testing.T) {
 			expectedErr: nil,
 		},
 		{
-			// Expected error is returned.
+			name:    "Expected error is returned",
 			timeout: time.Second,
 			fn: func() (runtime.Object, error) {
 				return nil, exampleErr
@@ -763,7 +766,7 @@ func TestFinishRequest(t *testing.T) {
 			expectedErr: exampleErr,
 		},
 		{
-			// Successful status object is returned as expected.
+			name:    "Successful status object is returned as expected",
 			timeout: time.Second,
 			fn: func() (runtime.Object, error) {
 				return successStatusObj, nil
@@ -772,22 +775,57 @@ func TestFinishRequest(t *testing.T) {
 			expectedErr: nil,
 		},
 		{
-			// Error status object is converted to StatusError.
+			name:    "Error status object is converted to StatusError",
 			timeout: time.Second,
 			fn: func() (runtime.Object, error) {
 				return errorStatusObj, nil
 			},
 			expectedObj: nil,
 			expectedErr: apierrors.FromObject(errorStatusObj),
 		},
+		{
+			name:    "Panic is propagated up",
+			timeout: time.Second,
+			fn: func() (runtime.Object, error) {
+				panic("my panic")
+				return nil, nil
+			},
+			expectedObj:   nil,
+			expectedErr:   nil,
+			expectedPanic: "my panic",
+		},
+		{
+			name:    "Panic is propagated with stack",
+			timeout: time.Second,
+			fn: func() (runtime.Object, error) {
+				panic("my panic")
+				return nil, nil
+			},
+			expectedObj:   nil,
+			expectedErr:   nil,
+			expectedPanic: "rest_test.go",
+		},
 	}
 	for i, tc := range testcases {
-		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()) {
-			t.Errorf("%d: unexpected err. expected: %v, got: %v", i, tc.expectedErr, err)
-		}
-		if !apiequality.Semantic.DeepEqual(obj, tc.expectedObj) {
-			t.Errorf("%d: unexpected obj. expected %#v, got %#v", i, tc.expectedObj, obj)
-		}
+		t.Run(tc.name, func(t *testing.T) {
+			defer func() {
+				r := recover()
+				switch {
+				case r == nil && len(tc.expectedPanic) > 0:
+					t.Errorf("expected panic containing '%s', got none", tc.expectedPanic)
+				case r != nil && len(tc.expectedPanic) == 0:
+					t.Errorf("unexpected panic: %v", r)
+				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)
+				}
+			}()
+			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()) {
+				t.Errorf("%d: unexpected err. expected: %v, got: %v", i, tc.expectedErr, err)
+			}
+			if !apiequality.Semantic.DeepEqual(obj, tc.expectedObj) {
+				t.Errorf("%d: unexpected obj. expected %#v, got %#v", i, tc.expectedObj, obj)
+			}
+		})
 	}
 }

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

@@ -22,6 +22,7 @@ import (
 	"fmt"
 	"net"
 	"net/http"
+	"runtime"
 	"sync"
 	"time"
 
@@ -87,16 +88,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,38 +52,47 @@ 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
 	defer func() {
 		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(*http.Request) (<-chan time.Time, func(), *apierrors.StatusError) {
+	handler := newHandler(sendResponse, doPanic, writeErrors)
+	ts := httptest.NewServer(withPanicRecovery(
+		WithTimeout(handler, func(req *http.Request) (<-chan time.Time, func(), *apierrors.StatusError) {
 			return 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"
 
 	"github.com/golang/glog"
 
@@ -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)
+		glog.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)
-			glog.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)