Merge lp:~pedronis/ubuntu-push/panic-to-500 into lp:ubuntu-push

[Samuele Pedroni]

introduce middleware in the http handling that recovers and converts panics into 500 errors, profit (remove 500 ad hoc code)

introduce middleware in the http handling that recovers and converts panics into 500 errors,

in the process change logger.Recoverf -> logger.PanicStackf which is less magical but more flexible,

profit (remove ad hoc 500 code)

[John Lenton (chipaca)]

Neat.

review: Approve

=== modified file 'logger/logger.go'
--- logger/logger.go	2014-01-14 15:35:20 +0000
+++ logger/logger.go	2014-01-16 16:26:46 +0000
@@ -31,8 +31,9 @@
 	Errorf(format string, v ...interface{})
 	// Fatalf logs an error and exists the program with os.Exit(1).
 	Fatalf(format string, v ...interface{})
-	// Recoverf recover from a possible panic and logs it.
-	Recoverf(format string, v ...interface{})
+	// PanicStackf logs a error message and a stacktrace, for use
+	// in panic recovery.
+	PanicStackf(format string, v ...interface{})
 	// Infof logs a info message.
 	Infof(format string, v ...interface{})
 	// Debugf logs a debug message.
@@ -77,14 +78,12 @@
 	osExit(1)
 }
 
-func (lg *simpleLogger) Recoverf(format string, v ...interface{}) {
-	if err := recover(); err != nil {
-		msg := fmt.Sprintf(format, v...)
-		stack := make([]byte, 8*1024) // Stack writes less but doesn't fail
-		stackWritten := runtime.Stack(stack, false)
-		stack = stack[:stackWritten]
-		lg.Printf("ERROR panic %v!! %s:\n%s", err, msg, stack)
-	}
+func (lg *simpleLogger) PanicStackf(format string, v ...interface{}) {
+	msg := fmt.Sprintf(format, v...)
+	stack := make([]byte, 8*1024) // Stack writes less but doesn't fail
+	stackWritten := runtime.Stack(stack, false)
+	stack = stack[:stackWritten]
+	lg.Printf("ERROR(PANIC) %s:\n%s", msg, stack)
 }
 
 func (lg *simpleLogger) Infof(format string, v ...interface{}) {

=== modified file 'logger/logger_test.go'
--- logger/logger_test.go	2014-01-14 15:35:20 +0000
+++ logger/logger_test.go	2014-01-16 16:26:46 +0000
@@ -18,8 +18,10 @@
 
 import (
 	"bytes"
+	"fmt"
 	. "launchpad.net/gocheck"
 	"os"
+	"runtime"
 	"testing"
 )
 
@@ -95,23 +97,33 @@
 	c.Check(buf.String(), Matches, `.* ERROR e5\n.* DEBUG d5\n.* INFO i5\n`)
 }
 
-func panicAndRecover(logger Logger, n int, doPanic bool) {
-	defer logger.Recoverf("%v %d", "panic", n)
+func panicAndRecover(logger Logger, n int, doPanic bool, line *int, ok *bool) {
+	defer func() {
+		if err := recover(); err != nil {
+			logger.PanicStackf("%v %d", err, n)
+		}
+	}()
+	_, _, *line, *ok = runtime.Caller(0)
 	if doPanic {
-		panic("Troubles")
+		panic("Troubles") // @ line + 2
 	}
 }
 
-func (s *loggerSuite) TestRecoverf(c *C) {
+func (s *loggerSuite) TestPanicStackfPanicScenario(c *C) {
 	buf := &bytes.Buffer{}
 	logger := NewSimpleLogger(buf, "error")
-	panicAndRecover(logger, 6, true)
-	c.Check(buf.String(), Matches, "(?s).* ERROR panic Troubles!! panic 6:.*panicAndRecover.*")
+	var line int
+	var ok bool
+	panicAndRecover(logger, 6, true, &line, &ok)
+	c.Assert(ok, Equals, true)
+	c.Check(buf.String(), Matches, fmt.Sprintf("(?s).* ERROR\\(PANIC\\) Troubles 6:.*panicAndRecover.*logger_test.go:%d.*", line+2))
 }
 
-func (s *loggerSuite) TestRecoverfNop(c *C) {
+func (s *loggerSuite) TestPanicStackfNoPanicScenario(c *C) {
 	buf := &bytes.Buffer{}
 	logger := NewSimpleLogger(buf, "error")
-	panicAndRecover(logger, 6, false)
+	var line int
+	var ok bool
+	panicAndRecover(logger, 6, false, &line, &ok)
 	c.Check(buf.String(), Equals, "")
 }

=== modified file 'server/api/handlers.go'
--- server/api/handlers.go	2014-01-14 15:35:20 +0000
+++ server/api/handlers.go	2014-01-16 16:26:46 +0000
@@ -25,7 +25,6 @@
 	"launchpad.net/ubuntu-push/logger"
 	"launchpad.net/ubuntu-push/server/broker"
 	"launchpad.net/ubuntu-push/server/store"
-	"log"
 	"net/http"
 )
 
@@ -125,10 +124,7 @@
 func respondError(writer http.ResponseWriter, apiErr *APIError) {
 	wireError, err := json.Marshal(apiErr)
 	if err != nil {
-		// xxx general 500 framework
-		log.Println("The provided string could not be marshaled into an error:", err)
-		http.Error(writer, "Internal Server Error", http.StatusInternalServerError)
-		return
+		panic(fmt.Errorf("couldn't marshal our own errors: %v", err))
 	}
 	writer.Header().Set("Content-type", JSONMediaType)
 	writer.WriteHeader(apiErr.StatusCode)

=== added file 'server/api/middleware.go'
--- server/api/middleware.go	1970-01-01 00:00:00 +0000
+++ server/api/middleware.go	2014-01-16 16:26:46 +0000
@@ -0,0 +1,40 @@
+/*
+ Copyright 2013-2014 Canonical Ltd.
+
+ This program is free software: you can redistribute it and/or modify it
+ under the terms of the GNU General Public License version 3, as published
+ by the Free Software Foundation.
+
+ This program is distributed in the hope that it will be useful, but
+ WITHOUT ANY WARRANTY; without even the implied warranties of
+ MERCHANTABILITY, SATISFACTORY QUALITY, or FITNESS FOR A PARTICULAR
+ PURPOSE.  See the GNU General Public License for more details.
+
+ You should have received a copy of the GNU General Public License along
+ with this program.  If not, see <http://www.gnu.org/licenses/>.
+*/
+
+package api
+
+import (
+	"fmt"
+	"launchpad.net/ubuntu-push/logger"
+	"net/http"
+)
+
+// PanicTo500Handler wraps another handler such that panics are recovered
+// and 500 reported.
+func PanicTo500Handler(h http.Handler, logger logger.Logger) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		defer func() {
+			if err := recover(); err != nil {
+				logger.PanicStackf("serving http: %v", err)
+				// best effort
+				w.Header().Set("Content-Type", "application/json")
+				w.WriteHeader(500)
+				fmt.Fprintf(w, `{"error":"internal","message":"INTERNAL SERVER ERROR"}`)
+			}
+		}()
+		h.ServeHTTP(w, req)
+	})
+}

=== added file 'server/api/middleware_test.go'
--- server/api/middleware_test.go	1970-01-01 00:00:00 +0000
+++ server/api/middleware_test.go	2014-01-16 16:26:46 +0000
@@ -0,0 +1,46 @@
+/*
+ Copyright 2013-2014 Canonical Ltd.
+
+ This program is free software: you can redistribute it and/or modify it
+ under the terms of the GNU General Public License version 3, as published
+ by the Free Software Foundation.
+
+ This program is distributed in the hope that it will be useful, but
+ WITHOUT ANY WARRANTY; without even the implied warranties of
+ MERCHANTABILITY, SATISFACTORY QUALITY, or FITNESS FOR A PARTICULAR
+ PURPOSE.  See the GNU General Public License for more details.
+
+ You should have received a copy of the GNU General Public License along
+ with this program.  If not, see <http://www.gnu.org/licenses/>.
+*/
+
+package api
+
+import (
+	"bytes"
+	. "launchpad.net/gocheck"
+	"launchpad.net/ubuntu-push/logger"
+	// "launchpad.net/ubuntu-push/testing"
+	"net/http"
+	"net/http/httptest"
+)
+
+type middlewareSuite struct{}
+
+var _ = Suite(&middlewareSuite{})
+
+func (s *middlewareSuite) TestPanicTo500Handler(c *C) {
+	buf := &bytes.Buffer{}
+	logger := logger.NewSimpleLogger(buf, "debug")
+	panicking := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		panic("panic in handler")
+	})
+
+	h := PanicTo500Handler(panicking, logger)
+	w := httptest.NewRecorder()
+	h.ServeHTTP(w, nil)
+	c.Check(w.Code, Equals, 500)
+	c.Check(buf.String(), Matches, "(?s).* ERROR\\(PANIC\\) serving http: panic in handler:.*")
+	c.Check(w.Header().Get("Content-Type"), Equals, "application/json")
+	c.Check(w.Body.String(), Equals, `{"error":"internal","message":"INTERNAL SERVER ERROR"}`)
+}

=== modified file 'server/dev/server.go'
--- server/dev/server.go	2014-01-14 15:35:20 +0000
+++ server/dev/server.go	2014-01-16 16:26:46 +0000
@@ -55,6 +55,7 @@
 		logger.Fatalf("start http listening: %v", err)
 	}
 	handler := api.MakeHandlersMux(sto, broker, logger)
+	handler = api.PanicTo500Handler(handler, logger)
 	logger.Infof("listening for http on %v", httpLst.Addr())
 	go func() {
 		err := RunHTTPServe(httpLst, handler, cfg)

=== modified file 'server/listener/listener.go'
--- server/listener/listener.go	2014-01-14 15:35:20 +0000
+++ server/listener/listener.go	2014-01-16 16:26:46 +0000
@@ -79,7 +79,11 @@
 			return err
 		}
 		go func() {
-			defer logger.Recoverf("terminating device connection")
+			defer func() {
+				if err := recover(); err != nil {
+					logger.PanicStackf("terminating device connection on: %v", err)
+				}
+			}()
 			session(conn)
 		}()
 	}

=== modified file 'server/listener/listener_test.go'
--- server/listener/listener_test.go	2014-01-14 15:35:20 +0000
+++ server/listener/listener_test.go	2014-01-16 16:26:46 +0000
@@ -227,7 +227,7 @@
 	go func() {
 		errCh <- lst.AcceptLoop(func(conn net.Conn) error {
 			defer conn.Close()
-			panic("session panic")
+			panic("session crash")
 		}, logger)
 	}()
 	listenerAddr := lst.Addr().String()
@@ -235,5 +235,5 @@
 	c.Assert(err, Not(IsNil))
 	lst.Close()
 	c.Check(<-errCh, ErrorMatches, ".*use of closed.*")
-	c.Check(buf.String(), Matches, "(?s).*session panic!! terminating device connection:\n.*AcceptLoop.*")
+	c.Check(buf.String(), Matches, "(?s).* ERROR\\(PANIC\\) terminating device connection on: session crash:.*AcceptLoop.*")
 }