Merge pull request #545 from 0xProject/fix/swallowedMethodHandlerCras…

…hedErrs rpc: log errors when RPC method panics
0xProject · Nov 20, 2019 · 6fc65d5 · 6fc65d5
2 parents 94511f4 + 3816c7d
commit 6fc65d5
Show file tree

Hide file tree

Showing 2 changed files with 88 additions and 5 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -16,6 +16,7 @@ This changelog is a work in progress and may contain notes for versions which ha
 - Changed the default port for `RPC_ADDR` from a random available port to `60557`. _Some_ documentation already assumed `60557` was the default port. Now all documentation has been updated for consistency with this change. ([#542](https://github.com/0xProject/0x-mesh/pull/542)). 
 - Fixed a potential nil pointer exception in log hooks ([#543](https://github.com/0xProject/0x-mesh/pull/543)).
 - Fixed a bug where successful closes of an rpc subscription were being reported as errors ([#544](https://github.com/0xProject/0x-mesh/pull/544)).
+- We now log the error and stack trace if an RPC method panics. Before, these errors were swallowed by the panic recovery logic in `go-ethereum`'s `rpc` package. ([#545](https://github.com/0xProject/0x-mesh/pull/545))
 
 ## v6.0.1-beta
 

diff --git a/cmd/mesh/rpc_handler.go b/cmd/mesh/rpc_handler.go
@@ -5,8 +5,10 @@ package main
 import (
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"net"
+	"runtime/debug"
 	"strings"
 	"time"
 
@@ -52,12 +54,28 @@ func listenRPC(app *core.App, config standaloneConfig, ctx context.Context) erro
 }
 
 // GetOrders is called when an RPC client calls GetOrders.
-func (handler *rpcHandler) GetOrders(page, perPage int, snapshotID string) (*rpc.GetOrdersResponse, error) {
+func (handler *rpcHandler) GetOrders(page, perPage int, snapshotID string) (result *rpc.GetOrdersResponse, err error) {
 	log.WithFields(map[string]interface{}{
 		"page":       page,
 		"perPage":    perPage,
 		"snapshotID": snapshotID,
 	}).Debug("received GetOrders request via RPC")
+	// Catch panics, log stack trace and return RPC error message
+	defer func() {
+		if r := recover(); r != nil {
+			internalErr, ok := r.(error)
+			if !ok {
+				// If r is not of type error, convert it.
+				internalErr = fmt.Errorf("Recovered from non-error: (%T) %v", r, r)
+			}
+			log.WithFields(log.Fields{
+				"error":      internalErr,
+				"method":     "GetOrders",
+				"stackTrace": string(debug.Stack()),
+			}).Printf("RPC method handler crashed")
+			err = errors.New("method handler crashed in GetOrders RPC call (check logs for stack trace)")
+		}
+	}()
 	getOrdersResponse, err := handler.app.GetOrders(page, perPage, snapshotID)
 	if err != nil {
 		if _, ok := err.(core.ErrSnapshotNotFound); ok {
@@ -71,11 +89,27 @@ func (handler *rpcHandler) GetOrders(page, perPage int, snapshotID string) (*rpc
 }
 
 // AddOrders is called when an RPC client calls AddOrders.
-func (handler *rpcHandler) AddOrders(signedOrdersRaw []*json.RawMessage, opts rpc.AddOrdersOpts) (*ordervalidator.ValidationResults, error) {
+func (handler *rpcHandler) AddOrders(signedOrdersRaw []*json.RawMessage, opts rpc.AddOrdersOpts) (results *ordervalidator.ValidationResults, err error) {
 	log.WithFields(log.Fields{
 		"count":  len(signedOrdersRaw),
 		"pinned": opts.Pinned,
 	}).Info("received AddOrders request via RPC")
+	// Catch panics, log stack trace and return RPC error message
+	defer func() {
+		if r := recover(); r != nil {
+			internalErr, ok := r.(error)
+			if !ok {
+				// If r is not of type error, convert it.
+				internalErr = fmt.Errorf("Recovered from non-error: (%T) %v", r, r)
+			}
+			log.WithFields(log.Fields{
+				"error":      internalErr,
+				"method":     "AddOrders",
+				"stackTrace": string(debug.Stack()),
+			}).Printf("RPC method handler crashed")
+			err = errors.New("method handler crashed in AddOrders RPC call (check logs for stack trace)")
+		}
+	}()
 	validationResults, err := handler.app.AddOrders(signedOrdersRaw, opts.Pinned)
 	if err != nil {
 		// We don't want to leak internal error details to the RPC client.
@@ -86,8 +120,24 @@ func (handler *rpcHandler) AddOrders(signedOrdersRaw []*json.RawMessage, opts rp
 }
 
 // AddPeer is called when an RPC client calls AddPeer,
-func (handler *rpcHandler) AddPeer(peerInfo peerstore.PeerInfo) error {
+func (handler *rpcHandler) AddPeer(peerInfo peerstore.PeerInfo) (err error) {
 	log.Debug("received AddPeer request via RPC")
+	// Catch panics, log stack trace and return RPC error message
+	defer func() {
+		if r := recover(); r != nil {
+			internalErr, ok := r.(error)
+			if !ok {
+				// If r is not of type error, convert it.
+				internalErr = fmt.Errorf("Recovered from non-error: (%T) %v", r, r)
+			}
+			log.WithFields(log.Fields{
+				"error":      internalErr,
+				"method":     "AddPeer",
+				"stackTrace": string(debug.Stack()),
+			}).Printf("RPC method handler crashed")
+			err = errors.New("method handler crashed in AddPeer RPC call (check logs for stack trace)")
+		}
+	}()
 	if err := handler.app.AddPeer(peerInfo); err != nil {
 		log.WithField("error", err.Error()).Error("internal error in AddPeer RPC call")
 		return constants.ErrInternal
@@ -96,8 +146,24 @@ func (handler *rpcHandler) AddPeer(peerInfo peerstore.PeerInfo) error {
 }
 
 // GetStats is called when an RPC client calls GetStats,
-func (handler *rpcHandler) GetStats() (*rpc.GetStatsResponse, error) {
+func (handler *rpcHandler) GetStats() (result *rpc.GetStatsResponse, err error) {
 	log.Debug("received GetStats request via RPC")
+	// Catch panics, log stack trace and return RPC error message
+	defer func() {
+		if r := recover(); r != nil {
+			internalErr, ok := r.(error)
+			if !ok {
+				// If r is not of type error, convert it.
+				internalErr = fmt.Errorf("Recovered from non-error: (%T) %v", r, r)
+			}
+			log.WithFields(log.Fields{
+				"error":      internalErr,
+				"method":     "GetStats",
+				"stackTrace": string(debug.Stack()),
+			}).Printf("RPC method handler crashed")
+			err = errors.New("method handler crashed in GetStats RPC call (check logs for stack trace)")
+		}
+	}()
 	getStatsResponse, err := handler.app.GetStats()
 	if err != nil {
 		log.WithField("error", err.Error()).Error("internal error in GetStats RPC call")
@@ -107,8 +173,24 @@ func (handler *rpcHandler) GetStats() (*rpc.GetStatsResponse, error) {
 }
 
 // SubscribeToOrders is called when an RPC client sends a `mesh_subscribe` request with the `orders` topic parameter
-func (handler *rpcHandler) SubscribeToOrders(ctx context.Context) (*ethrpc.Subscription, error) {
+func (handler *rpcHandler) SubscribeToOrders(ctx context.Context) (result *ethrpc.Subscription, err error) {
 	log.Debug("received order event subscription request via RPC")
+	// Catch panics, log stack trace and return RPC error message
+	defer func() {
+		if r := recover(); r != nil {
+			internalErr, ok := r.(error)
+			if !ok {
+				// If r is not of type error, convert it.
+				internalErr = fmt.Errorf("Recovered from non-error: (%T) %v", r, r)
+			}
+			log.WithFields(log.Fields{
+				"error":      internalErr,
+				"method":     "SubscribeToOrders",
+				"stackTrace": string(debug.Stack()),
+			}).Printf("RPC method handler crashed")
+			err = errors.New("method handler crashed in SubscribeToOrders RPC call (check logs for stack trace)")
+		}
+	}()
 	subscription, err := SetupOrderStream(ctx, handler.app)
 	if err != nil {
 		log.WithField("error", err.Error()).Error("internal error in `mesh_subscribe` to `orders` RPC call")