Merge cockroachdb#154037

154037: util/ctxgroup: print recovered panic stacks during crash r=jeffswenson a=jeffswenson

When ctxgroup recovers a panic in a worker to be rethrown in Wait(), it uses errors.WithStack to try to capture the stack to the original panic, and subsequent recover, in the error that is stored to be rethrown on the Wait goroutine. And indeed, WithStack captures it... but only to have it ignored and not printed by the runtime crash handler, which just invokes Error(), if/when the rethrown panic bubbles up if unrecovered.

This makes such panics _very_ hard to debug: all information about where they were actually raised is gone, making this rethrow-on-Wait actually much worse than just not recovering at all.

This changes the capture-and-rethrow to wrap the captured error in a thin wrapper that overrides .Error() to incldue the stack, so that it is printed by the runtime crash handler if a rethrown panic makes it there.

Release note: none.
Epic: none.
Informs: cockroachdb#153347

Co-authored-by: David Taylor <[email protected]>

Author: craig[bot]

pkg/util/ctxgroup/ctxgroup.go

@@ -116,6 +116,7 @@ package ctxgroup
 
 import (
 	"context"
+	"fmt"
 
 	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
 	"github.com/cockroachdb/errors"
@@ -147,7 +148,7 @@ func (g Group) Wait() error {
 	err := g.wrapped.Wait()
 
 	if g.panicMu.payload != nil {
-		panic(g.panicMu.payload)
+		panic(verboseError{g.panicMu.payload})
 	}
 
 	if err != nil {
@@ -224,15 +225,39 @@ func GoAndWait(ctx context.Context, fs ...func(ctx context.Context) error) error
 }
 
 // wrapPanic turns r into an error if it is not one already.
-//
-// TODO(dt): consider raw recovered payload as well.
-//
-// TODO(dt): replace this with logcrash.PanicAsError after moving that to a new
-// standalone pkg (since we cannot depend on `util/log` here) and teaching it to
-// preserve the original payload.
 func wrapPanic(depth int, r interface{}) error {
+	// If r is already a verboseError, we remove the `verboseError` wrapper
+	// because it will be reapplied when the panic is rethrown by wait. The stack
+	// trace is attached to the inner error. Its desirable to remove the verbose
+	// format wrapper from the child because the parent verbose wrapper will
+	// print the child errors .Error() method and the child's stack. If we left
+	// the wrapper in place, this would print the child error's stack twice.
+	if err, ok := r.(verboseError); ok {
+		return errors.WithStackDepth(err.error, depth+1)
+	}
 	if err, ok := r.(error); ok {
 		return errors.WithStackDepth(err, depth+1)
 	}
 	return errors.NewWithDepthf(depth+1, "panic: %v", r)
 }
+
+type verboseError struct {
+	error // always a errors.WithStack.withStack
+}
+
+// Error overrides WithStack.withStack()'s Error to include the stack.
+//
+// Typically withstack's Error() just delegates to the underlying error and
+// requires formatting with %+v to print the stacktrace. However this wrapper is
+// used to wrap a recovered panic that is *rethrown*. If this rethrown panic is
+// not recovered, the runtime will eventually crash and print it... by calling
+// .Error(), which will *not* indicate the stack to the original panic we so
+// dutifully captured by using WithStack. So override .Error() to include the
+// stack, but leave .Format() to fallthrough to withStack as usual.
+func (p verboseError) Error() string {
+	return fmt.Sprintf("%+v", p.error)
+}
+
+func (p verboseError) Unwrap() error {
+	return p.error
+}

pkg/util/ctxgroup/ctxgroup_test.go

@@ -44,6 +44,13 @@ func funcThatPanics(x interface{}) {
 	panic(x)
 }
 
+func deferThatPanics() {
+	defer func() {
+		panic("in deferred panic")
+	}()
+	funcThatPanics("in func panic")
+}
+
 func TestPanic(t *testing.T) {
 	defer leaktest.AfterTest(t)()
 
@@ -65,3 +72,51 @@ func TestPanic(t *testing.T) {
 		}()
 	})
 }
+
+func TestPanicInDefer(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+
+	defer func() {
+		r := recover()
+		require.NotNil(t, r, "expected panic from Wait")
+		err := r.(error)
+		require.Contains(t, err.Error(), "in deferred panic", "expected deferred panic message")
+		require.Contains(t, err.Error(), "deferThatPanics", "expected deferThatPanics in stack")
+		require.Contains(t, err.Error(), "funcThatPanics", "expected deferThatPanics in stack")
+		t.Log("recovered: ", err.Error())
+	}()
+
+	g := WithContext(context.Background())
+	g.GoCtx(func(_ context.Context) error { deferThatPanics(); return errors.New("unseen") })
+	t.Fatal(g.Wait(), "unreachable if we hit expected panic in Wait")
+}
+
+func innerGroup() error {
+	g := WithContext(context.Background())
+	g.GoCtx(func(_ context.Context) error { funcThatPanics("inner"); return nil })
+	return g.Wait()
+}
+
+func outerGroup() error {
+	g := WithContext(context.Background())
+	g.GoCtx(func(_ context.Context) error { return innerGroup() })
+	return g.Wait()
+}
+
+func TestNestedContextGroup(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+
+	defer func() {
+		r := recover()
+		require.NotNil(t, r, "expected panic from Wait")
+		err := r.(error)
+		require.Contains(t, err.Error(), "inner", "expected inner panic message")
+		require.Contains(t, err.Error(), "innerGroup", "expected innerGroup in stack")
+		require.Contains(t, err.Error(), "outerGroup", "expected outerGroup in stack")
+		t.Log("recovered: ", err.Error())
+	}()
+
+	g := WithContext(context.Background())
+	g.GoCtx(func(_ context.Context) error { return outerGroup() })
+	t.Fatal(g.Wait(), "unreachable if we hit expected panic in Wait")
+}