Merge pull request #75853 from roycaihw/fix/use-standard-stacktrace

apimachinery & apiserver: use stacktrace in the stdlib

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

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

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"
@@ -195,10 +194,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
 			}

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

@@ -92,23 +92,27 @@ 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() {
 			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)]
 				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)
 		}