Log stack when panic

middlewares/recover.go

@@ -2,6 +2,7 @@ package middlewares
 
 import (
 	"net/http"
+	"runtime"
 
 	"github.com/containous/traefik/log"
 	"github.com/urfave/negroni"
@@ -10,7 +11,7 @@ import (
 // RecoverHandler recovers from a panic in http handlers
 func RecoverHandler(next http.Handler) http.Handler {
 	fn := func(w http.ResponseWriter, r *http.Request) {
-		defer recoverFunc(w)
+		defer recoverFunc(w, r)
 		next.ServeHTTP(w, r)
 	}
 	return http.HandlerFunc(fn)
@@ -19,23 +20,31 @@ func RecoverHandler(next http.Handler) http.Handler {
 // NegroniRecoverHandler recovers from a panic in negroni handlers
 func NegroniRecoverHandler() negroni.Handler {
 	fn := func(w http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
-		defer recoverFunc(w)
+		defer recoverFunc(w, r)
 		next.ServeHTTP(w, r)
 	}
 	return negroni.HandlerFunc(fn)
 }
 
-func recoverFunc(w http.ResponseWriter) {
+func recoverFunc(w http.ResponseWriter, r *http.Request) {
 	if err := recover(); err != nil {
-		if shouldLogPanic(err) {
-			log.Errorf("Recovered from panic in http handler: %+v", err)
-			http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
-		} else {
-			log.Debugf("HTTP handler has been aborted: %v", err)
+		if !shouldLogPanic(err) {
+			log.Debugf("Request has been aborted [%s - %s]: %v", r.RemoteAddr, r.URL, err)
+			return
 		}
+
+		log.Errorf("Recovered from panic in HTTP handler [%s - %s]: %+v", r.RemoteAddr, r.URL, err)
+
+		const size = 64 << 10
+		buf := make([]byte, size)
+		buf = buf[:runtime.Stack(buf, false)]
+		log.Errorf("Stack: %s", buf)
+
+		http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 	}
 }
 
+// https://github.com/golang/go/blob/a0d6420d8be2ae7164797051ec74fa2a2df466a1/src/net/http/server.go#L1761-L1775
 // https://github.com/golang/go/blob/c33153f7b416c03983324b3e8f869ce1116d84bc/src/net/http/httputil/reverseproxy.go#L284
 func shouldLogPanic(panicValue interface{}) bool {
 	return panicValue != nil && panicValue != http.ErrAbortHandler

safe/routine.go

@@ -145,7 +145,7 @@ func GoWithRecover(goroutine func(), customRecover func(err interface{})) {
 
 func defaultRecoverGoroutine(err interface{}) {
 	log.Errorf("Error in Go routine: %s", err)
-	debug.PrintStack()
+	log.Errorf("Stack: %s", debug.Stack())
 }
 
 // OperationWithRecover wrap a backoff operation in a Recover

safe/routine_test.go

@@ -13,9 +13,12 @@ import (
 func TestNewPoolContext(t *testing.T) {
 	type testKeyType string
 	testKey := testKeyType("test")
+
 	ctx := context.WithValue(context.Background(), testKey, "test")
 	p := NewPool(ctx)
+
 	retCtx := p.Ctx()
+
 	retCtxVal, ok := retCtx.Value(testKey).(string)
 	if !ok || retCtxVal != "test" {
 		t.Errorf("Pool.Ctx() did not return a derived context, got %#v, expected context with test value", retCtx)
@@ -52,7 +55,8 @@ func (tr *fakeRoutine) routine(stop chan bool) {
 
 func TestPoolWithCtx(t *testing.T) {
 	testRoutine := newFakeRoutine()
-	tt := []struct {
+
+	testCases := []struct {
 		desc string
 		fn   func(*Pool)
 	}{
@@ -70,19 +74,20 @@ func TestPoolWithCtx(t *testing.T) {
 			},
 		},
 	}
-	for _, tc := range tt {
-		tc := tc
-		t.Run(tc.desc, func(t *testing.T) {
+
+	for _, test := range testCases {
+		test := test
+		t.Run(test.desc, func(t *testing.T) {
 			// These subtests cannot be run in parallel, since the testRoutine
 			// is shared across the subtests.
 			p := NewPool(context.Background())
 			timer := time.NewTimer(500 * time.Millisecond)
 			defer timer.Stop()
 
-			tc.fn(p)
+			test.fn(p)
 			defer p.Cleanup()
 			if len(p.routinesCtx) != 1 {
-				t.Fatalf("After %s, Pool did have %d goroutineCtxs, expected 1", tc.desc, len(p.routinesCtx))
+				t.Fatalf("After %s, Pool did have %d goroutineCtxs, expected 1", test.desc, len(p.routinesCtx))
 			}
 
 			testDone := make(chan bool, 1)
@@ -91,6 +96,7 @@ func TestPoolWithCtx(t *testing.T) {
 				p.Cleanup()
 				testDone <- true
 			}()
+
 			select {
 			case <-timer.C:
 				testRoutine.Lock()
@@ -105,8 +111,9 @@ func TestPoolWithCtx(t *testing.T) {
 
 func TestPoolWithStopChan(t *testing.T) {
 	testRoutine := newFakeRoutine()
-	ctx := context.Background()
-	p := NewPool(ctx)
+
+	p := NewPool(context.Background())
+
 	timer := time.NewTimer(500 * time.Millisecond)
 	defer timer.Stop()
 
@@ -121,6 +128,7 @@ func TestPoolWithStopChan(t *testing.T) {
 		p.Cleanup()
 		testDone <- true
 	}()
+
 	select {
 	case <-timer.C:
 		testRoutine.Lock()
@@ -133,8 +141,9 @@ func TestPoolWithStopChan(t *testing.T) {
 
 func TestPoolStartWithStopChan(t *testing.T) {
 	testRoutine := newFakeRoutine()
-	ctx := context.Background()
-	p := NewPool(ctx)
+
+	p := NewPool(context.Background())
+
 	timer := time.NewTimer(500 * time.Millisecond)
 	defer timer.Stop()
 

safe/safe_test.go

@@ -5,19 +5,25 @@ import "testing"
 func TestSafe(t *testing.T) {
 	const ts1 = "test1"
 	const ts2 = "test2"
+
 	s := New(ts1)
+
 	result, ok := s.Get().(string)
 	if !ok {
 		t.Fatalf("Safe.Get() failed, got type '%T', expected string", s.Get())
 	}
+
 	if result != ts1 {
 		t.Errorf("Safe.Get() failed, got '%s', expected '%s'", result, ts1)
 	}
+
 	s.Set(ts2)
+
 	result, ok = s.Get().(string)
 	if !ok {
 		t.Fatalf("Safe.Get() after Safe.Set() failed, got type '%T', expected string", s.Get())
 	}
+
 	if result != ts2 {
 		t.Errorf("Safe.Get() after Safe.Set() failed, got '%s', expected '%s'", result, ts2)
 	}