Further cleanup error handling.

Prevent double logging of panic errors.
Recover middleware solely converts panics to errors.
ErrorHandler middleware takes care of logging / building the response.

Author: raphael

middleware/error_handler.go

@@ -20,8 +20,7 @@ func ErrorHandler(suppressInternal bool) goa.Middleware {
 				return nil
 			}
 
-			goa.LogInfo(ctx, "Default error handler", "err", e)
-			status := 500
+			status := http.StatusInternalServerError
 			var respBody interface{}
 			if err, ok := e.(*goa.Error); ok {
 				status = err.Status
@@ -32,10 +31,15 @@ func ErrorHandler(suppressInternal bool) goa.Middleware {
 				rw.Header().Set("Content-Type", "text/plain")
 			}
 			if status >= 500 && status < 600 {
-				goa.LogError(ctx, e.Error())
+				reqID := ctx.Value(reqIDKey)
+				if reqID == nil {
+					reqID = shortID()
+					ctx = context.WithValue(ctx, reqIDKey, reqID)
+				}
+				goa.LogError(ctx, "uncaught error", "id", reqID, "msg", respBody)
 				if suppressInternal {
 					rw.Header().Set("Content-Type", goa.ErrorMediaIdentifier)
-					respBody = goa.ErrInternal("internal error, detail suppressed")
+					respBody = goa.ErrInternal("internal error [%s]", reqID)
 				}
 			}
 			return goa.ContextResponse(ctx).Send(ctx, status, respBody)

middleware/error_handler_test.go

@@ -5,6 +5,8 @@ import (
 	"errors"
 	"fmt"
 	"net/http"
+	"regexp"
+	"strings"
 
 	"golang.org/x/net/context"
 
@@ -39,9 +41,12 @@ var _ = Describe("ErrorHandler", func() {
 	})
 
 	Context("with a handler returning a Go error", func() {
+		var requestCtx context.Context
+
 		BeforeEach(func() {
 			service = newService(nil)
 			h = func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
+				requestCtx = ctx
 				return errors.New("boom")
 			}
 		})
@@ -63,9 +68,11 @@ var _ = Describe("ErrorHandler", func() {
 				Ω(rw.ParentHeader["Content-Type"]).Should(Equal([]string{goa.ErrorMediaIdentifier}))
 				err := service.Decode(&decoded, bytes.NewBuffer(rw.Body), "application/json")
 				Ω(err).ShouldNot(HaveOccurred())
-				Ω(fmt.Sprintf("%v", decoded)).Should(Equal(fmt.Sprintf("%v", *goa.ErrInternal("internal error, detail suppressed"))))
+				msg := fmt.Sprintf("%v", *goa.ErrInternal(`internal error [zzz]`))
+				msg = regexp.QuoteMeta(msg)
+				msg = strings.Replace(msg, "zzz", ".+", 1)
+				Ω(fmt.Sprintf("%v", decoded)).Should(MatchRegexp(msg))
 			})
-
 		})
 	})
 

middleware/recover.go

@@ -1,7 +1,6 @@
 package middleware
 
 import (
-	"errors"
 	"fmt"
 	"net/http"
 	"runtime"
@@ -12,49 +11,27 @@ import (
 	"golang.org/x/net/context"
 )
 
-// Recover is a middleware that recovers panics and returns an internal error response.
+// Recover is a middleware that recovers panics and maps them to errors.
 func Recover() goa.Middleware {
 	return func(h goa.Handler) goa.Handler {
 		return func(ctx context.Context, rw http.ResponseWriter, req *http.Request) (err error) {
 			defer func() {
 				if r := recover(); r != nil {
-					if ctx != nil {
-						switch x := r.(type) {
-						case string:
-							err = fmt.Errorf("panic: %s", x)
-						case error:
-							err = x
-						default:
-							err = errors.New("unknown panic")
-						}
-						const size = 64 << 10 // 64KB
-						buf := make([]byte, size)
-						buf = buf[:runtime.Stack(buf, false)]
-						lines := strings.Split(string(buf), "\n")
-						stack := lines[3:]
-						status := http.StatusInternalServerError
-						var message string
-						reqID := ctx.Value(reqIDKey)
-						if reqID != nil {
-							message = fmt.Sprintf(
-								"%s\nRefer to the following token when contacting support: %s",
-								http.StatusText(status),
-								reqID)
-						}
-						goa.LogError(ctx, "PANIC", "error", err, "stack", strings.Join(stack, "\n"))
-
-						// note we must respond or else a 500 with "unhandled request" is the
-						// default response.
-						if message == "" {
-							// without the logger and/or request id (from middleware) we can
-							// only return the full error message for reference purposes. it
-							// is unlikely to make sense to the caller unless they understand
-							// the source code.
-							message = err.Error()
-						}
-						rw.WriteHeader(status)
-						rw.Write([]byte(message))
+					var msg string
+					switch x := r.(type) {
+					case string:
+						msg = fmt.Sprintf("panic: %s", x)
+					case error:
+						msg = fmt.Sprintf("panic: %s", x)
+					default:
+						msg = "unknown panic"
 					}
+					const size = 64 << 10 // 64KB
+					buf := make([]byte, size)
+					buf = buf[:runtime.Stack(buf, false)]
+					lines := strings.Split(string(buf), "\n")
+					stack := lines[3:]
+					err = fmt.Errorf("%s\n%s", msg, strings.Join(stack, "\n"))
 				}
 			}()
 			return h(ctx, rw, req)

middleware/recover_test.go

@@ -1,6 +1,7 @@
 package middleware_test
 
 import (
+	"fmt"
 	"net/http"
 
 	"golang.org/x/net/context"
@@ -12,17 +13,50 @@ import (
 )
 
 var _ = Describe("Recover", func() {
-	It("recovers", func() {
-		service := newService(nil)
-		h := func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
-			panic("boom")
-		}
+	var h goa.Handler
+	var err error
+
+	JustBeforeEach(func() {
 		rg := middleware.Recover()(h)
-		service.Encoder(goa.NewJSONEncoder, "*/*")
-		rw := new(testResponseWriter)
-		ctx := newContext(service, rw, nil, nil)
-		err := rg(ctx, rw, nil)
-		Ω(err).Should(HaveOccurred())
-		Ω(err.Error()).Should(Equal("panic: boom"))
+		err = rg(nil, nil, nil)
+	})
+
+	Context("with a handler that panics with a string", func() {
+		BeforeEach(func() {
+			h = func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
+				panic("boom")
+			}
+		})
+
+		It("creates an error from the panic message", func() {
+			Ω(err).Should(HaveOccurred())
+			Ω(err.Error()).Should(HavePrefix("panic: boom\n"))
+		})
+	})
+
+	Context("with a handler that panics with an error", func() {
+		BeforeEach(func() {
+			h = func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
+				panic(fmt.Errorf("boom"))
+			}
+		})
+
+		It("creates an error from the panic error message", func() {
+			Ω(err).Should(HaveOccurred())
+			Ω(err.Error()).Should(HavePrefix("panic: boom\n"))
+		})
+	})
+
+	Context("with a handler that panics with something else", func() {
+		BeforeEach(func() {
+			h = func(ctx context.Context, rw http.ResponseWriter, req *http.Request) error {
+				panic(42)
+			}
+		})
+
+		It("creates a generic error message", func() {
+			Ω(err).Should(HaveOccurred())
+			Ω(err.Error()).Should(HavePrefix("unknown panic\n"))
+		})
 	})
 })

service.go

@@ -245,19 +245,11 @@ func (ctrl *Controller) MuxHandler(name string, hdlr Handler, unm Unmarshaler) M
 			}
 		}
 
-		// Invoke middleware chain, wrap writer to capture response status and length
+		// Invoke middleware chain, errors should be caught earlier, e.g. by ErrorHandler middleware
 		if err := handler(ctx, ContextResponse(ctx), req); err != nil {
-			LastResortErrorHandler(ctx, rw, req, err)
+			LogError(ctx, "Last resort error handler", "err", err)
+			respBody := fmt.Sprintf("Internal error: %s", err) // Sprintf catches panics
+			ContextResponse(ctx).Send(ctx, 500, respBody)
 		}
 	}
 }
-
-// LastResortErrorHandler is the last thing that can handle an error propagating up the middleware
-// chain and turns all errors into a response indicating an internal error.
-// Ideally all errors are handled at a lower level in the middleware chain so they
-// can be logged properly.
-func LastResortErrorHandler(ctx context.Context, rw http.ResponseWriter, req *http.Request, e error) {
-	LogError(ctx, "Last resort error handler", "err", e)
-	respBody := fmt.Sprintf("Internal error: %s", e) // Sprintf catches panics
-	ContextResponse(ctx).Send(ctx, 500, respBody)
-}