add rpc panic recovery middleware #240

yutongp · 2017-02-12T00:50:50Z

refer to #240
I talked with @abhinav. He said the panic recovery middleware does not exist yet. If they add one, that one will be in rpcinit with go-common integration.
In that case, I think fx need one as well for sentry and metrics integrations.

mention-bot · 2017-02-12T00:50:51Z

@yutongp, thanks for your PR! By analyzing the history of the files in this pull request, we identified @anuptalwalkar, @alsamylkin and @sectioneight to be potential reviewers.

yutongp · 2017-02-12T00:52:35Z

modules/rpc/handler.go

+func panicRecovery(ctx context.Context) {
+	if err := recover(); err != nil {
+		stats.RPCPanicCounter.Inc(1)
+		fx.Logger(ctx).Error("Panic recovered serving request", "error", err)


should I also log debug.Stack() here as well? raven does send stack trace to sentry, but even users are not running with sentry, they will miss the stack trace.

We have an interceptor for error logs, and print the stack trace by default. @alsamylkin to confirm that it works in this case as well.

We should also print some request specific information here.

It will not log a stacktrace here, because err can technically not implement error interface :)
The easiest way to get the stacktrace, is to wrap err with errors.Wrap and log it, then you'll get a stacktrace for free.

what kind of request specific information we are thinking about to log here?

@glibsm We are talking about logging additional information about panic: request, how can we stripe the PII information from it and safely log.

I see, I think there are too many threads in here that got mixed up

PII concern applies to all logging and sentry, lets not try to solve it only for YARPC

PII in response on failure is what we should be talking about here, and returning a custom error seems to satisfy the need.

so what's the conclusion we have here? keep what I have right now?
I agree obscuring PII is a seperate issue, before we have a story about that, not logging request make sense to me.

Why not logging the request makes sense?

synced offline, it does make sense to not log request information, because it is not safe in general case.

coveralls · 2017-02-12T00:54:10Z

Coverage increased (+0.04%) to 92.784% when pulling b05d5d2 on yutongp:yutong/rpc_panic into 13f8007 on uber-go:master.

madhuravi · 2017-02-13T00:52:58Z

modules/rpc/handler.go

@@ -30,6 +30,8 @@ import (
 	"go.uber.org/yarpc/api/transport"
 )

+const panicRespnose = "Server Error"


typo: panicResponse

madhuravi · 2017-02-13T00:55:04Z

modules/rpc/handler.go

+		fx.Logger(ctx).Error("Panic recovered serving request", "error", err)
+		// rethrow panic back to yarpc
+		// before https://github.com/yarpc/yarpc-go/issues/734 fixed, throw a generic error.
+		panic(panicRespnose)


it should be something along the lines of panic(err.Error()). server error is too generic and does not convey much.

I think we should return general error message to client (since client can be something out of DC) so we don't leak something like: server use golang, server has nil pointer etc. Meaningful info can be present through introspector and sentry to service owners .

madhuravi · 2017-02-13T00:56:12Z

modules/rpc/handler.go

+		stats.RPCPanicCounter.Inc(1)
+		fx.Logger(ctx).Error("Panic recovered serving request", "error", err)
+		// rethrow panic back to yarpc
+		// before https://github.com/yarpc/yarpc-go/issues/734 fixed, throw a generic error.


From the issue, it looks like yarpc already implements a panic handler. Why does UberFx need one?

Yarpc only log to stderr, this is more for log to all hooks in fx like sentry. Of course, if filebeat is almost ready, it will be not that useful for us. But should be still useful for open source when they hook with sentry

coveralls · 2017-02-13T18:30:22Z

Coverage increased (+0.04%) to 92.784% when pulling 0904456 on yutongp:yutong/rpc_panic into 13f8007 on uber-go:master.

ghost · 2017-02-13T18:42:48Z

modules/rpc/handler.go

+		fx.Logger(ctx).Error("Panic recovered serving request", "error", err)
+		// rethrow panic back to yarpc
+		// before https://github.com/yarpc/yarpc-go/issues/734 fixed, throw a generic error.
+		panic(panicResponse)


Why do we rethrow panic here? I thought the point of this filter was to not cause panics, like https://github.com/uber-go/fx/blob/master/modules/uhttp/filters.go#L102

Im not sure what the correct behavior should be here, but I don't think we should just "swallow" the panic. We do want to let the caller know something went wrong

Even if we re-throw in this case, we got a chance to record a metric and log an error. Any other processing that we like can also be added easily

Services can return errors, that's what we should do in this case. Panic here is an inconsistent behavior between different modules.

the reason I rethrow a panic is: here in https://github.com/yarpc/yarpc-go/blob/61fa69b4a04faa5d1dc57b5a2ce44f93c16e6485/api/transport/handler.go#L100
yarpc does have recover from panic and log the panic to std output. but I don't like how they return the panic msg back to client, so I rethrow a more generic msg...

Ok, since they documented recovery, its fine with me to panic here.

glibsm · 2017-02-13T19:04:45Z

modules/rpc/handler.go

@@ -88,3 +90,27 @@ func authorize(ctx context.Context, host service.Host) (context.Context, error)
 	}
 	return ctx, nil
 }
+
+type panicInboundMiddleware struct{}


this follows the naming convention with contextInboundMiddleware and authInboundMiddleware right now
maybe change all of them in another diff?

glibsm · 2017-02-13T19:05:11Z

modules/rpc/handler.go

@@ -30,6 +30,8 @@ import (
 	"go.uber.org/yarpc/api/transport"
 )

+const panicResponse = "Server Error"


two things:

This var looks familiar from another diff

Underscore the const variables, please

ya, I want to through a same general error msg for panic. do we need to share this const between rpc and uhttp?

sure

glibsm · 2017-02-13T19:07:32Z

modules/rpc/handler.go

+		fx.Logger(ctx).Error("Panic recovered serving request", "error", err)
+		// rethrow panic back to yarpc
+		// before https://github.com/yarpc/yarpc-go/issues/734 fixed, throw a generic error.
+		panic(panicResponse)


Im not sure what the correct behavior should be here, but I don't think we should just "swallow" the panic. We do want to let the caller know something went wrong

Even if we re-throw in this case, we got a chance to record a metric and log an error. Any other processing that we like can also be added easily

coveralls · 2017-02-14T05:05:31Z

Coverage increased (+0.04%) to 92.779% when pulling d71bcf9 on yutongp:yutong/rpc_panic into 9de6ba0 on uber-go:master.

ghost · 2017-02-14T05:53:55Z

modules/rpc/yarpc.go

@@ -126,10 +126,12 @@ func (c *dispatcherController) addDefaultMiddleware(host service.Host) {
 	cfg := yarpcConfig{
 		inboundMiddleware: []middleware.UnaryInbound{
 			contextInboundMiddleware{host},
+			panicInboundMiddleware{},


I think panic middleware should be the very first in the slice, to catch all possible issues.

but then we don't have the logger with host in context

ghost · 2017-02-14T05:54:59Z

modules/rpc/handler_test.go

@@ -116,3 +116,32 @@ func (f fakeOnewayHandler) HandleOneway(ctx context.Context, p *transport.Reques
 	assert.NotNil(f.t, ctx)
 	return errors.New("oneway handle")
 }
+
+func TestInboundMiddleware_panic(t *testing.T) {
+	defer testPanicHandler(t)


nit: use t.Parallel()?

ya, then maybe we should apply parallel for all tests in this file. Let me pull another PR to address that. I do want to do some refactor as well.

ghost · 2017-02-14T05:59:08Z

modules/rpc/handler_test.go

+	assert.EqualValues(t, r, _panicResponse)
+}
+
+type panicUnaryHandler struct{}


nit: name it alwaysPanicUnary?

ghost · 2017-02-14T06:00:02Z

modules/rpc/handler.go

+
+func panicRecovery(ctx context.Context) {
+	if err := recover(); err != nil {
+		stats.RPCPanicCounter.Inc(1)


I don't see where this counter update is tested..

is there way to test metrics count/timer is called? I would like to test in #251 as well. Maybe you can point me somewhere metrics is tested.

Here is an example:
https://github.com/uber-go/fx/blob/master/modules/task/execution_test.go#L172

ghost

Couple nits, but overall looks good.

Lets wait for Tuesday, to let others to review.

yutongp · 2017-02-14T07:58:33Z

modules/rpc/handler.go

+func panicRecovery(ctx context.Context) {
+	if err := recover(); err != nil {
+		stats.RPCPanicCounter.Inc(1)
+		fx.Logger(ctx).Error("Panic recovered serving request", "error", errors.Errorf("panic: %+v", err))


@alsamylkin I cannot use errors.Wrap since it takes in an error type. let me know if I am doing it wrong. This is to get the stack trace.

fx.Loger(ctx).Error("Panic recovered serving request", "error", errors.Wrap(err, "panic in handler"))

errors.Wrap asked for an error interface, recover only returns interface{}, so we cannot use errors.Wrap here. I will change the text

coveralls · 2017-02-14T07:58:44Z

Coverage increased (+0.04%) to 92.779% when pulling e1c28fa on yutongp:yutong/rpc_panic into 9de6ba0 on uber-go:master.

ascandella · 2017-02-14T10:43:14Z

modules/rpc/handler.go

@@ -28,8 +28,12 @@ import (
 	"go.uber.org/fx/modules/rpc/internal/stats"
 	"go.uber.org/fx/service"
 	"go.uber.org/yarpc/api/transport"
+
+	"github.com/pkg/errors"


nit: this should be grouped with yarpc since it's a "3rd-party" import

coveralls · 2017-02-14T18:56:55Z

Coverage increased (+0.04%) to 92.776% when pulling c4574f3 on yutongp:yutong/rpc_panic into 9de6ba0 on uber-go:master.

coveralls · 2017-02-15T00:23:20Z

Coverage increased (+0.04%) to 92.65% when pulling cc4b154 on yutongp:yutong/rpc_panic into 734b80d on uber-go:master.

yutongp commented Feb 12, 2017

View reviewed changes

ascandella requested review from abhinav and glibsm February 12, 2017 20:05

madhuravi reviewed Feb 13, 2017

View reviewed changes

ghost suggested changes Feb 13, 2017

View reviewed changes

glibsm reviewed Feb 13, 2017

View reviewed changes

yutongp added 4 commits February 13, 2017 20:16

add a rpc panic recovery middleware

fa9f503

fix typo

a1c9886

really fix typo

e7cb200

address glibsm comment

d71bcf9

yutongp force-pushed the yutong/rpc_panic branch from 0904456 to d71bcf9 Compare February 14, 2017 05:02

ghost reviewed Feb 14, 2017

View reviewed changes

modules/rpc/handler_test.go Outdated

assert.EqualValues(t, r, _panicResponse)

}

type panicUnaryHandler struct{}

Copy link

ghost Feb 14, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: name it alwaysPanicUnary?

ghost reviewed Feb 14, 2017

View reviewed changes

ghost approved these changes Feb 14, 2017

View reviewed changes

address Alex comments

e1c28fa

yutongp commented Feb 14, 2017

View reviewed changes

ascandella approved these changes Feb 14, 2017

View reviewed changes

address Aiden comments

c4574f3

Alex added 2 commits February 14, 2017 16:13

Merge branch 'master' into yutong/rpc_panic

1352997

Merge logger

cc4b154

ghost merged commit 0626e44 into uber-go:master Feb 15, 2017

yutongp deleted the yutong/rpc_panic branch February 15, 2017 03:41

yutongp mentioned this pull request Feb 15, 2017

panic logging middleware #236

Closed

This pull request was closed.

add rpc panic recovery middleware #240

add rpc panic recovery middleware #240

Conversation

yutongp commented Feb 12, 2017 • edited

mention-bot commented Feb 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Feb 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Feb 13, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yutongp Feb 13, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Feb 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghost left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ascandella Feb 14, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Feb 14, 2017

Choose a reason for hiding this comment

coveralls commented Feb 14, 2017

coveralls commented Feb 15, 2017

yutongp commented Feb 12, 2017 •

edited

yutongp Feb 13, 2017 •

edited

ascandella Feb 14, 2017 •

edited