From 12e7648a7faf87c07d55b719a78400b2429577eb Mon Sep 17 00:00:00 2001 From: Alex Grintsvayg Date: Fri, 29 May 2020 13:42:12 -0400 Subject: [PATCH] include stack traces with recovered panics --- internal/errors/errors.go | 39 ++++++++++++++++++++++++++--- internal/errors/errors_test.go | 33 ++++++++++++++++++++++++ internal/monitor/middleware.go | 30 ++++++++-------------- internal/monitor/middleware_test.go | 4 +-- 4 files changed, 82 insertions(+), 24 deletions(-) diff --git a/internal/errors/errors.go b/internal/errors/errors.go index 57a96793..c7b4d7d5 100644 --- a/internal/errors/errors.go +++ b/internal/errors/errors.go @@ -10,7 +10,7 @@ import ( ) // The maximum number of stack frames on any error. -const maxStackDepth = 50 +const maxStackDepth = 100 // traced is an error with an attached stack trace type traced struct { @@ -97,8 +97,7 @@ func wrap(skip int, e interface{}, fmtParams ...interface{}) *traced { } var stack []uintptr - type stackTracer interface{ StackTrace() pkgerr.StackTrace } // interop with pkg/errors stack - if withStack, ok := e.(stackTracer); ok { + if withStack, ok := e.(interface{ StackTrace() pkgerr.StackTrace }); ok { // interop with pkg/errors stack // get their stacktrace pkgStack := withStack.StackTrace() stack = make([]uintptr, len(pkgStack)) @@ -164,3 +163,37 @@ func HasTrace(err error) bool { _, ok := err.(*traced) return ok } + +/* +Recover is similar to the bulitin `recover()`, except it includes a stack trace as well +Since `recover()` only works when called inside a deferred function (but not any function +called by it), you should call Recover() as follows + + err := func() (e error) { + defer errors.Recover(&e) + funcThatMayPanic() + return e + }() + +*/ +func Recover(e *error) { + p := recover() + if p == nil { + return + } + + err, ok := p.(error) + if !ok { + err = fmt.Errorf("%v", p) + } + + stack := make([]uintptr, maxStackDepth) + length := runtime.Callers(4, stack[:]) + stack = stack[:length] + + *e = &traced{ + err: err, + stack: stack, + prefix: "panic", + } +} diff --git a/internal/errors/errors_test.go b/internal/errors/errors_test.go index 7c7c2dc3..a9129188 100644 --- a/internal/errors/errors_test.go +++ b/internal/errors/errors_test.go @@ -6,6 +6,7 @@ import ( pkg "github.com/pkg/errors" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestErr_MultipleLayersOfWrapping(t *testing.T) { @@ -20,3 +21,35 @@ func TestErr_MultipleLayersOfWrapping(t *testing.T) { assert.True(t, base.Is(our2, pkg1)) assert.True(t, base.Is(our2, our1)) } + +func TestRecover(t *testing.T) { + var err error + require.NotPanics(t, func() { + err = func() (e error) { + defer Recover(&e) + itPanics() + return nil + }() + }) + + assert.Error(t, err) + assert.Contains(t, err.Error(), "who shall dwell in these worlds") + + withTrace, ok := err.(*traced) + assert.True(t, ok) + + stackFrames := withTrace.StackFrames() + assert.Equal(t, "itPanicsDeeper", stackFrames[0].Name) + assert.Equal(t, "itPanics", stackFrames[1].Name) + + traceStr := Trace(err) + assert.Contains(t, traceStr, "who shall dwell in these worlds") +} + +func itPanics() { + itPanicsDeeper() +} + +func itPanicsDeeper() { + panic("But who shall dwell in these worlds if they be inhabited?… Are we or they Lords of the World?… And how are all things made for man?") +} diff --git a/internal/monitor/middleware.go b/internal/monitor/middleware.go index b2b78d28..2464af9e 100644 --- a/internal/monitor/middleware.go +++ b/internal/monitor/middleware.go @@ -5,7 +5,6 @@ import ( "encoding/json" "fmt" "net/http" - "runtime/debug" "github.com/lbryio/lbrytv/config" "github.com/lbryio/lbrytv/internal/errors" @@ -80,19 +79,10 @@ func ErrorLoggingMiddleware(next http.Handler) http.Handler { // Record response from next handler, recovering any panics therein recorder := &responseRecorder{} - recoveredErr, stack := func() (err error, stack []byte) { - defer func() { - if p := recover(); p != nil { - var ok bool - err, ok = p.(error) - if !ok { - err = fmt.Errorf("%v", p) - } - stack = debug.Stack() - } - }() + recoveredErr := func() (err error) { + defer errors.Recover(&err) next.ServeHTTP(recorder, r.WithContext(ctx)) - return err, stack + return err }() // No panics. Send recorded response to the real writer @@ -106,18 +96,20 @@ func ErrorLoggingMiddleware(next http.Handler) http.Handler { // There was a panic. Handle it and send error response - recordPanic(recoveredErr, r, recorder, stack) + recordPanic(recoveredErr, r, recorder) - if config.IsProduction() { - stack = nil + stack := "" + if !config.IsProduction() { + stack = errors.Trace(recoveredErr) } + responses.AddJSONContentType(w) rsp, _ := json.Marshal(jsonrpc.RPCResponse{ JSONRPC: "2.0", Error: &jsonrpc.RPCError{ Code: -1, Message: recoveredErr.Error(), - Data: string(stack), + Data: stack, }, }) w.WriteHeader(http.StatusInternalServerError) @@ -147,7 +139,7 @@ func recordRequestError(r *http.Request, rec *responseRecorder) { }) } -func recordPanic(err error, r *http.Request, rec *responseRecorder, stack []byte) { +func recordPanic(err error, r *http.Request, rec *responseRecorder) { snippetLen := len(rec.Body.String()) if snippetLen > 500 { snippetLen = 500 @@ -158,7 +150,7 @@ func recordPanic(err error, r *http.Request, rec *responseRecorder, stack []byte "url": r.URL.Path, "status": rec.StatusCode, "response": rec.Body.String()[:snippetLen], - }).Error(fmt.Errorf("RECOVERED PANIC: %v, trace: %s", err, string(stack))) + }).Error(fmt.Errorf("RECOVERED PANIC: %v, trace: %s", err, errors.Trace(err))) hub := sentry.GetHubFromContext(r.Context()) if hub == nil { diff --git a/internal/monitor/middleware_test.go b/internal/monitor/middleware_test.go index e56cc15a..0ec9d3f0 100644 --- a/internal/monitor/middleware_test.go +++ b/internal/monitor/middleware_test.go @@ -36,7 +36,7 @@ var testTableErrorLoggingMiddleware = []middlewareTestRow{ panic("panic ensued") }, expectedStatus: http.StatusInternalServerError, - expectedJSONMessage: "panic ensued", + expectedJSONMessage: "panic: panic ensued", expectedLogEntry: map[string]interface{}{ "method": "POST", "url": "/some-endpoint", @@ -44,7 +44,7 @@ var testTableErrorLoggingMiddleware = []middlewareTestRow{ "response": "everything good so far...", }, expectedLogLevel: log.ErrorLevel, - expectedLogStartsWith: "RECOVERED PANIC: panic ensued", + expectedLogStartsWith: "RECOVERED PANIC: panic: panic ensued", }, {