proxy: refactor filter panic handling (#2194)

In case of filter panic proxy abrupts filter chain and responds with 500 InternalServerError.

Signed-off-by: Alexander Yastrebov <[email protected]>

Signed-off-by: Alexander Yastrebov <[email protected]>

go.mod

@@ -47,6 +47,7 @@ require (
 	golang.org/x/oauth2 v0.0.0-20211104180415-d3ed0bb246c8
 	golang.org/x/sync v0.0.0-20210220032951-036812b2e83c
 	golang.org/x/term v0.0.0-20210927222741-03fcf44c2211
+	golang.org/x/time v0.3.0
 	gopkg.in/alecthomas/kingpin.v2 v2.2.6
 	gopkg.in/square/go-jose.v2 v2.6.0
 	gopkg.in/yaml.v2 v2.4.0

go.sum

@@ -1128,7 +1128,8 @@ golang.org/x/time v0.0.0-20190308202827-9d24e82272b4/go.mod h1:tRJNPiyCQ0inRvYxb
 golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/time v0.0.0-20200416051211-89c76fbcd5d1/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/time v0.0.0-20200630173020-3af7569d3a1e/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
-golang.org/x/time v0.0.0-20210723032227-1f47c861a9ac h1:7zkz7BUtwNFFqcowJ+RIgu2MaV/MapERkDIy+mwPyjs=
+golang.org/x/time v0.3.0 h1:rg5rLMjNzMS1RkNLzCG38eapWhnYLFYXDXj2gOlr8j4=
+golang.org/x/time v0.3.0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/tools v0.0.0-20180221164845-07fd8470d635/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20180525024113-a5b4c53f6e8b/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=

proxy/context.go

@@ -35,7 +35,6 @@ type context struct {
 	originalRequest      *http.Request
 	originalResponse     *http.Response
 	outgoingHost         string
-	debugFilterPanics    []interface{}
 	outgoingDebugRequest *http.Request
 	executionCounter     int
 	startServe           time.Time

proxy/debug.go

@@ -2,7 +2,6 @@ package proxy
 
 import (
 	"encoding/json"
-	"fmt"
 	"io"
 	"net/http"
 
@@ -36,19 +35,17 @@ type (
 		ResponseModBody string             `json:"response_mod_body,omitempty"`
 		ResponseModErr  string             `json:"response_mod_error,omitempty"`
 		ProxyError      string             `json:"proxy_error,omitempty"`
-		FilterPanics    []string           `json:"filter_panics,omitempty"`
 		Filters         []*eskip.Filter    `json:"filters,omitempty"`
 		Predicates      []*eskip.Predicate `json:"predicates,omitempty"`
 	}
 )
 
 type debugInfo struct {
-	route        *eskip.Route
-	incoming     *http.Request
-	outgoing     *http.Request
-	response     *http.Response
-	err          error
-	filterPanics []interface{}
+	route    *eskip.Route
+	incoming *http.Request
+	outgoing *http.Request
+	response *http.Response
+	err      error
 }
 
 func convertRequest(r *http.Request) *debugRequest {
@@ -121,10 +118,6 @@ func convertDebugInfo(d *debugInfo) debugDocument {
 		doc.ProxyError = d.err.Error()
 	}
 
-	for _, fp := range d.filterPanics {
-		doc.FilterPanics = append(doc.FilterPanics, fmt.Sprint(fp))
-	}
-
 	return doc
 }
 

proxy/debug_test.go

@@ -173,12 +173,10 @@ func TestDebug(t *testing.T) {
 		"error",
 		debugInfo{
 			err: errors.New("test error"),
-			filterPanics: []interface{}{
-				errors.New("panic one"),
-				errors.New("panic two")}},
+		},
 		debugDocument{
-			ProxyError:   "test error",
-			FilterPanics: []string{"panic one", "panic two"}},
+			ProxyError: "test error",
+		},
 	}} {
 		compareStrings := func(smsg string, got, expect []string) {
 			if len(got) != len(expect) {
@@ -277,7 +275,5 @@ func TestDebug(t *testing.T) {
 		if got.ProxyError != ti.expect.ProxyError {
 			t.Error(ti.msg, "failed to convert proxy error")
 		}
-
-		compareStrings("filter panics", got.FilterPanics, ti.expect.FilterPanics)
 	}
 }

proxy/proxy.go

@@ -20,6 +20,8 @@ import (
 	"time"
 	"unicode/utf8"
 
+	"golang.org/x/time/rate"
+
 	ot "github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
 	"github.com/zalando/skipper/circuit"
@@ -337,6 +339,7 @@ type Proxy struct {
 	auditLogHook             chan struct{}
 	clientTLS                *tls.Config
 	hostname                 string
+	onPanicSometimes         rate.Sometimes
 }
 
 // proxyError is used to wrap errors during proxying and to indicate
@@ -717,31 +720,10 @@ func WithParams(p Params) *Proxy {
 		upgradeAuditLogErr:       os.Stderr,
 		clientTLS:                tr.TLSClientConfig,
 		hostname:                 hostname,
+		onPanicSometimes:         rate.Sometimes{First: 3, Interval: 1 * time.Minute},
 	}
 }
 
-var caughtPanic = false
-
-// tryCatch executes function `p` and `onErr` if `p` panics
-// onErr will receive a stack trace string of the first panic
-// further panics are ignored for efficiency reasons
-func tryCatch(p func(), onErr func(err interface{}, stack string)) {
-	defer func() {
-		if err := recover(); err != nil {
-			s := ""
-			if !caughtPanic {
-				buf := make([]byte, 1024)
-				l := runtime.Stack(buf, false)
-				s = string(buf[:l])
-				caughtPanic = true
-			}
-			onErr(err, s)
-		}
-	}()
-
-	p()
-}
-
 // applies filters to a request
 func (p *Proxy) applyFiltersToRequest(f []*routing.RouteFilter, ctx *context) []*routing.RouteFilter {
 	if len(f) == 0 {
@@ -756,20 +738,11 @@ func (p *Proxy) applyFiltersToRequest(f []*routing.RouteFilter, ctx *context) []
 	for _, fi := range f {
 		start := time.Now()
 		filterTracing.logStart(fi.Name)
-		tryCatch(func() {
-			ctx.setMetricsPrefix(fi.Name)
-			fi.Request(ctx)
-			p.metrics.MeasureFilterRequest(fi.Name, start)
-		}, func(err interface{}, stack string) {
-			if p.flags.Debug() {
-				// these errors are collected for the debug mode to be able
-				// to report in the response which filters failed.
-				ctx.debugFilterPanics = append(ctx.debugFilterPanics, err)
-				return
-			}
+		ctx.setMetricsPrefix(fi.Name)
 
-			p.log.Errorf("error while processing filter during request: %s: %v (%s)", fi.Name, err, stack)
-		})
+		fi.Request(ctx)
+
+		p.metrics.MeasureFilterRequest(fi.Name, start)
 		filterTracing.logEnd(fi.Name)
 
 		filters = append(filters, fi)
@@ -793,20 +766,11 @@ func (p *Proxy) applyFiltersToResponse(filters []*routing.RouteFilter, ctx *cont
 		fi := filters[last-i]
 		start := time.Now()
 		filterTracing.logStart(fi.Name)
-		tryCatch(func() {
-			ctx.setMetricsPrefix(fi.Name)
-			fi.Response(ctx)
-			p.metrics.MeasureFilterResponse(fi.Name, start)
-		}, func(err interface{}, stack string) {
-			if p.flags.Debug() {
-				// these errors are collected for the debug mode to be able
-				// to report in the response which filters failed.
-				ctx.debugFilterPanics = append(ctx.debugFilterPanics, err)
-				return
-			}
+		ctx.setMetricsPrefix(fi.Name)
 
-			p.log.Errorf("error while processing filters during response: %s: %v (%s)", fi.Name, err, stack)
-		})
+		fi.Response(ctx)
+
+		p.metrics.MeasureFilterResponse(fi.Name, start)
 		filterTracing.logEnd(fi.Name)
 	}
 
@@ -1050,7 +1014,29 @@ func newRatelimitError(settings ratelimit.Settings, retryAfter int) error {
 	}
 }
 
-func (p *Proxy) do(ctx *context) error {
+// copied from debug.PrintStack
+func stack() []byte {
+	buf := make([]byte, 1024)
+	for {
+		n := runtime.Stack(buf, false)
+		if n < len(buf) {
+			return buf[:n]
+		}
+		buf = make([]byte, 2*len(buf))
+	}
+}
+
+func (p *Proxy) do(ctx *context) (err error) {
+	defer func() {
+		if r := recover(); r != nil {
+			p.onPanicSometimes.Do(func() {
+				p.log.Errorf("stacktrace of panic caused by: %v:\n%s", r, stack())
+			})
+
+			err = fmt.Errorf("panic caused by: %v", r)
+		}
+	}()
+
 	if ctx.executionCounter > p.maxLoops {
 		return errMaxLoopbacksReached
 	}
@@ -1081,8 +1067,7 @@ func (p *Proxy) do(ctx *context) error {
 	// proxy global setting
 	if !ctx.wasExecuted() {
 		if settings, retryAfter := p.limiters.Check(ctx.request); retryAfter > 0 {
-			rerr := newRatelimitError(settings, retryAfter)
-			return rerr
+			return newRatelimitError(settings, retryAfter)
 		}
 	}
 	// every time the context is used for a request the context executionCounter is incremented
@@ -1204,11 +1189,10 @@ func retryable(ctx *context, perr *proxyError) bool {
 func (p *Proxy) serveResponse(ctx *context) {
 	if p.flags.Debug() {
 		dbgResponse(ctx.responseWriter, &debugInfo{
-			route:        &ctx.route.Route,
-			incoming:     ctx.originalRequest,
-			outgoing:     ctx.outgoingDebugRequest,
-			response:     ctx.response,
-			filterPanics: ctx.debugFilterPanics,
+			route:    &ctx.route.Route,
+			incoming: ctx.originalRequest,
+			outgoing: ctx.outgoingDebugRequest,
+			response: ctx.response,
 		})
 
 		return
@@ -1283,11 +1267,10 @@ func (p *Proxy) errorResponse(ctx *context, err error) {
 
 	if p.flags.Debug() {
 		di := &debugInfo{
-			incoming:     ctx.originalRequest,
-			outgoing:     ctx.outgoingDebugRequest,
-			response:     ctx.response,
-			err:          err,
-			filterPanics: ctx.debugFilterPanics,
+			incoming: ctx.originalRequest,
+			outgoing: ctx.outgoingDebugRequest,
+			response: ctx.response,
+			err:      err,
 		}
 
 		if ctx.route != nil {