From 3efb632b316f495c98285f42c35aca9b5f089f6f Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 24 Oct 2016 15:26:57 +0100 Subject: [PATCH 1/5] Log panicking HTTP requests Whilst Go does this by default (does not `exit`), it logs to the std logger which isn't written to the log file. Handle all panicking `OnIncomingRequests`. --- src/github.com/matrix-org/go-neb/server/server.go | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/src/github.com/matrix-org/go-neb/server/server.go b/src/github.com/matrix-org/go-neb/server/server.go index fa1bb7f..98d74d1 100644 --- a/src/github.com/matrix-org/go-neb/server/server.go +++ b/src/github.com/matrix-org/go-neb/server/server.go @@ -6,6 +6,7 @@ import ( log "github.com/Sirupsen/logrus" "github.com/matrix-org/go-neb/errors" "net/http" + "runtime/debug" ) // JSONRequestHandler represents an interface that must be satisfied in order to respond to incoming @@ -41,7 +42,17 @@ func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { "method": req.Method, "url": req.URL, }) - logger.Print(">>> Incoming request") + logger.Print("Incoming request") + defer func() { + if r := recover(); r != nil { + logger.WithField("error", r).Errorf( + "Request panicked!\n%s", debug.Stack(), + ) + jsonErrorResponse( + w, req, &errors.HTTPError{nil, "Internal Server Error", 500}, + ) + } + }() res, httpErr := handler.OnIncomingRequest(req) // Set common headers returned regardless of the outcome of the request From ce414ea58609878753b939d0abc4949181c896a0 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 24 Oct 2016 15:37:09 +0100 Subject: [PATCH 2/5] Prevent panicking code triggered by matrix events from taking down the entire process Specifically, this protects panicking `!commands` and expansions. --- .../matrix-org/go-neb/matrix/worker.go | 20 +++++++++++++++++++ .../matrix-org/go-neb/server/server.go | 2 +- 2 files changed, 21 insertions(+), 1 deletion(-) diff --git a/src/github.com/matrix-org/go-neb/matrix/worker.go b/src/github.com/matrix-org/go-neb/matrix/worker.go index c5770f5..3674601 100644 --- a/src/github.com/matrix-org/go-neb/matrix/worker.go +++ b/src/github.com/matrix-org/go-neb/matrix/worker.go @@ -1,5 +1,10 @@ package matrix +import ( + log "github.com/Sirupsen/logrus" + "runtime/debug" +) + // Worker processes incoming events and updates the Matrix client's data structures. It also informs // any attached listeners of the new events. type Worker struct { @@ -38,6 +43,21 @@ func (worker *Worker) notifyListeners(event *Event) { } func (worker *Worker) onSyncHTTPResponse(res syncHTTPResponse) { + defer func() { + if r := recover(); r != nil { + userID := "" + if worker.client != nil { + userID = worker.client.UserID + } + log.WithFields(log.Fields{ + "panic": r, + "user_id": userID, + }).Errorf( + "onSyncHTTPResponse panicked!\n%s", debug.Stack(), + ) + } + }() + for roomID, roomData := range res.Rooms.Join { room := worker.client.getOrCreateRoom(roomID) for _, event := range roomData.State.Events { diff --git a/src/github.com/matrix-org/go-neb/server/server.go b/src/github.com/matrix-org/go-neb/server/server.go index 98d74d1..91e64e8 100644 --- a/src/github.com/matrix-org/go-neb/server/server.go +++ b/src/github.com/matrix-org/go-neb/server/server.go @@ -45,7 +45,7 @@ func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { logger.Print("Incoming request") defer func() { if r := recover(); r != nil { - logger.WithField("error", r).Errorf( + logger.WithField("panic", r).Errorf( "Request panicked!\n%s", debug.Stack(), ) jsonErrorResponse( From 7ab9794623bf6e4d5f1f8503eba1a1fddc40e728 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 24 Oct 2016 15:44:04 +0100 Subject: [PATCH 3/5] Protect panicking poll loops from taking down the entire process --- src/github.com/matrix-org/go-neb/polling/polling.go | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/src/github.com/matrix-org/go-neb/polling/polling.go b/src/github.com/matrix-org/go-neb/polling/polling.go index 2500d30..d4b6bbc 100644 --- a/src/github.com/matrix-org/go-neb/polling/polling.go +++ b/src/github.com/matrix-org/go-neb/polling/polling.go @@ -5,6 +5,7 @@ import ( "github.com/matrix-org/go-neb/clients" "github.com/matrix-org/go-neb/database" "github.com/matrix-org/go-neb/types" + "runtime/debug" "sync" "time" ) @@ -71,6 +72,15 @@ func pollLoop(service types.Service, ts int64) { "service_id": service.ServiceID(), "service_type": service.ServiceType(), }) + + defer func() { + if r := recover(); r != nil { + logger.WithField("panic", r).Errorf( + "pollLoop panicked!\n%s", debug.Stack(), + ) + } + }() + poller, ok := service.(types.Poller) if !ok { logger.Error("Service is not a Poller.") From 92ac46e9258bab0efe2ab44902fccfbb4ff4f6a6 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 24 Oct 2016 16:04:32 +0100 Subject: [PATCH 4/5] Factor out a Protect() function for incoming HTTP requests --- src/github.com/matrix-org/go-neb/goneb.go | 4 +-- .../matrix-org/go-neb/server/server.go | 32 +++++++++++++------ 2 files changed, 25 insertions(+), 11 deletions(-) diff --git a/src/github.com/matrix-org/go-neb/goneb.go b/src/github.com/matrix-org/go-neb/goneb.go index 9afaf38..7b73ca2 100644 --- a/src/github.com/matrix-org/go-neb/goneb.go +++ b/src/github.com/matrix-org/go-neb/goneb.go @@ -193,9 +193,9 @@ func main() { http.Handle("/metrics", prometheus.Handler()) http.Handle("/test", prometheus.InstrumentHandler("test", server.MakeJSONAPI(&heartbeatHandler{}))) wh := &webhookHandler{db: db, clients: clients} - http.HandleFunc("/services/hooks/", prometheus.InstrumentHandlerFunc("webhookHandler", wh.handle)) + http.HandleFunc("/services/hooks/", prometheus.InstrumentHandlerFunc("webhookHandler", server.Protect(wh.handle))) rh := &realmRedirectHandler{db: db} - http.HandleFunc("/realms/redirects/", prometheus.InstrumentHandlerFunc("realmRedirectHandler", rh.handle)) + http.HandleFunc("/realms/redirects/", prometheus.InstrumentHandlerFunc("realmRedirectHandler", server.Protect(rh.handle))) // Read exclusively from the config file if one was supplied. // Otherwise, add HTTP listeners for new Services/Sessions/Clients/etc. diff --git a/src/github.com/matrix-org/go-neb/server/server.go b/src/github.com/matrix-org/go-neb/server/server.go index 91e64e8..b240914 100644 --- a/src/github.com/matrix-org/go-neb/server/server.go +++ b/src/github.com/matrix-org/go-neb/server/server.go @@ -35,17 +35,18 @@ func WithCORSOptions(handler http.HandlerFunc) http.HandlerFunc { } } -// MakeJSONAPI creates an HTTP handler which always responds to incoming requests with JSON responses. -func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { +// Protect panicking HTTP requests from taking down the entire process, and log them using +// the correct logger, returning a 500 with a JSON response rather than abruptly closing the +// connection. +func Protect(handler http.HandlerFunc) http.HandlerFunc { return func(w http.ResponseWriter, req *http.Request) { - logger := log.WithFields(log.Fields{ - "method": req.Method, - "url": req.URL, - }) - logger.Print("Incoming request") defer func() { if r := recover(); r != nil { - logger.WithField("panic", r).Errorf( + log.WithFields(log.Fields{ + "panic": r, + "method": req.Method, + "url": req.URL, + }).Errorf( "Request panicked!\n%s", debug.Stack(), ) jsonErrorResponse( @@ -53,6 +54,19 @@ func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { ) } }() + handler(w, req) + } +} + +// MakeJSONAPI creates an HTTP handler which always responds to incoming requests with JSON responses. +func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { + return Protect(func(w http.ResponseWriter, req *http.Request) { + logger := log.WithFields(log.Fields{ + "method": req.Method, + "url": req.URL, + }) + logger.Print("Incoming request") + res, httpErr := handler.OnIncomingRequest(req) // Set common headers returned regardless of the outcome of the request @@ -78,7 +92,7 @@ func MakeJSONAPI(handler JSONRequestHandler) http.HandlerFunc { resBytes = r } w.Write(resBytes) - } + }) } func jsonErrorResponse(w http.ResponseWriter, req *http.Request, httpErr *errors.HTTPError) { From 236c97d279d0dc8a1d927688b64b5357275ab838 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 24 Oct 2016 17:07:55 +0100 Subject: [PATCH 5/5] Tests and comments --- .../matrix-org/go-neb/polling/polling.go | 2 ++ .../matrix-org/go-neb/server/server_test.go | 29 +++++++++++++++++++ 2 files changed, 31 insertions(+) create mode 100644 src/github.com/matrix-org/go-neb/server/server_test.go diff --git a/src/github.com/matrix-org/go-neb/polling/polling.go b/src/github.com/matrix-org/go-neb/polling/polling.go index d4b6bbc..0a84a92 100644 --- a/src/github.com/matrix-org/go-neb/polling/polling.go +++ b/src/github.com/matrix-org/go-neb/polling/polling.go @@ -74,6 +74,8 @@ func pollLoop(service types.Service, ts int64) { }) defer func() { + // Kill the poll loop entirely as it is likely that whatever made us panic will + // make us panic again. We can whine bitterly about it though. if r := recover(); r != nil { logger.WithField("panic", r).Errorf( "pollLoop panicked!\n%s", debug.Stack(), diff --git a/src/github.com/matrix-org/go-neb/server/server_test.go b/src/github.com/matrix-org/go-neb/server/server_test.go new file mode 100644 index 0000000..920d0ae --- /dev/null +++ b/src/github.com/matrix-org/go-neb/server/server_test.go @@ -0,0 +1,29 @@ +package server + +import ( + "net/http" + "net/http/httptest" + "testing" +) + +func TestProtect(t *testing.T) { + mockWriter := httptest.NewRecorder() + mockReq, _ := http.NewRequest("GET", "http://example.com/foo", nil) + h := Protect(func(w http.ResponseWriter, req *http.Request) { + var array []string + w.Write([]byte(array[5])) // NPE + }) + + h(mockWriter, mockReq) + + expectCode := 500 + if mockWriter.Code != expectCode { + t.Errorf("TestProtect wanted HTTP status %d, got %d", expectCode, mockWriter.Code) + } + + expectBody := `{"message":"Internal Server Error"}` + actualBody := mockWriter.Body.String() + if actualBody != expectBody { + t.Errorf("TestProtect wanted body %s, got %s", expectBody, actualBody) + } +}