etcdserver/api/v3rpc: debug user cancellation and log warning for rest #9105

spzala · 2018-01-05T16:48:06Z

The context error with cancel code is typically for user cancellation which
should be at debug level. For other error codes we should display a warning.

Fixes #9085

Contributing guidelines

Please read our contribution workflow before submitting a pull request.

spzala · 2018-01-05T16:50:36Z

@xiang90 @gyuho does the changes make sense? Do we need to cover any more errors? Thanks!

codecov-io · 2018-01-05T17:53:15Z

Codecov Report

❗ No coverage uploaded for pull request base (master@6f76e46). Click here to learn what that means.
The diff coverage is 65.62%.

@@            Coverage Diff            @@
##             master    #9105   +/-   ##
=========================================
  Coverage          ?   75.93%           
=========================================
  Files             ?      359           
  Lines             ?    29987           
  Branches          ?        0           
=========================================
  Hits              ?    22771           
  Misses            ?     5626           
  Partials          ?     1590

Impacted Files	Coverage Δ
etcdserver/api/v3rpc/lease.go	`86.48% <50%> (ø)`
etcdserver/api/v3rpc/watch.go	`84.12% <68.75%> (ø)`
etcdserver/api/v3rpc/util.go	`86.66% <75%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6f76e46...c2185e1. Read the comment docs.

xiang90 · 2018-01-05T17:56:16Z

etcdserver/api/v3rpc/watch.go

@@ -140,7 +140,11 @@ func (ws *watchServer) Watch(stream pb.Watch_WatchServer) (err error) {
 	// deadlock when calling sws.close().
 	go func() {
 		if rerr := sws.recvLoop(); rerr != nil {
-			plog.Debugf("failed to receive watch request from gRPC stream (%q)", rerr.Error())
+			if stream.Context().Err() == context.Canceled {
+				plog.Debugf("failed to receive watch request from gRPC stream 11 (%q)", rerr.Error())


remove 11?

ooops lol .. :( yes

xiang90 · 2018-01-05T17:57:00Z

etcdserver/api/v3rpc/watch.go

@@ -140,7 +140,11 @@ func (ws *watchServer) Watch(stream pb.Watch_WatchServer) (err error) {
 	// deadlock when calling sws.close().
 	go func() {
 		if rerr := sws.recvLoop(); rerr != nil {
-			plog.Debugf("failed to receive watch request from gRPC stream (%q)", rerr.Error())
+			if stream.Context().Err() == context.Canceled {


both context.Cancel and context.DeadlineExceeded should be ignored i think.

Also we should have a shared function for all streaming API logs #8939 (e.g. lease keepalive).

@gyuho thanks! I just learned how to use lease :-) and could see the related log messages. So also modifying the message on LOC 110 (for user cancelled lease) in #8939 is what your suggesting right? I know you suggested to refer to the toErr function in etcd/clientv3/client.go in the issue discussion but I believe that was just to learn about different error code and not to make any changes there. Thanks!

Yes, just like we do in clientv3, there should be an error parsing function on this rerr error. Convert it to gRPC *status.statusError and match the error code. If the error is canceled or deadline exceeded, we log with debug level.

xiang90 · 2018-01-05T17:59:04Z

can we manually test this PR?

1. setup one member etcd cluster with debug level logging
2. create a watcher without timeout against it
3. cancel the watcher
4. make sure log is printed at debug level not at waring level

1. setup one member etcd cluster with debug level logging
2. create a watcher with a short timeout against it
3. wait for the timeout to exceed
4. make sure log is printed at debug level not at waring level

spzala · 2018-01-05T18:09:04Z

@xiang90 +1 thanks, I actually pretty much already tested the first scenario before submitting commit - i.e. manually cancelling watcher and making sure that warning is printed but not debug message. Testing more per your suggestion.

xiang90 · 2018-01-05T18:13:26Z

manually cancelling watcher and making sure that warning is printed but not debug message.

I think if you manually callcelling watcher, the log should be at debug level not warning level?

spzala · 2018-01-05T18:46:50Z

Hmm..so by default the debug level is off right? For example, when I run etcd as ./bin/etcd and then cancel watcher I don't see any debug message (something I tried earlier). If I run with debug on explicitly (just tried it now) as ./bin/etcd --debug then I see debug message as below:

$./bin/etcdctl watch foo
^C
$

$./bin/etcd --debug
....
....
2018-01-05 13:42:22.660676 D | etcdserver/api/v3rpc: failed to receive watch request from gRPC stream 11 ("rpc error: code = Canceled desc = context canceled")

xiang90 · 2018-01-05T18:49:17Z

correct. and what you saw is the expected behavior.

spzala · 2018-01-05T18:54:37Z

:-) OK, prefect. Thought so too :-).

spzala · 2018-01-06T00:51:59Z

I have tested following, manual and auto interruption for watch and lease keep-alive, with new commit:

$ ./bin/etcdctl watch foo
^C
$

$ timeout 3 ./bin/etcdctl watch foo

$ ./bin/etcdctl lease keep-alive 694d60c8e16b2003
lease 694d60c8e16b2003 keepalived with TTL(30)
^C
$

$ timeout 3 ./bin/etcdctl lease keep-alive 694d60c8e16b2003
lease 694d60c8e16b2003 keepalived with TTL(30)
$

etcd was ran with and without --debug

gyuho · 2018-01-06T00:56:13Z

etcdserver/api/v3rpc/lease.go

@@ -107,7 +110,13 @@ func (ls *LeaseServer) leaseKeepAlive(stream pb.Lease_LeaseKeepAliveServer) erro
 			return nil
 		}
 		if err != nil {
-			plog.Debugf("failed to receive lease keepalive request from gRPC stream (%q)", err.Error())
+			ev, _ := status.FromError(err)


@spzala Let's wrap this as a separate function inside etcdserver/api/v3rpc.

func isClientCtxErr(err error) error { ev, _ := status.FromError(err) ... return true // when code == codes.Canceled || code == codes.DeadlineExceeded }

OK, yup, makes sense specially that we are doing for all of the messages. Thanks!

gyuho · 2018-01-06T00:58:29Z

@spzala We should do this for all streaming error handling (watch,keepalive receive/send). There are total 6 error we need to handle (see for others https://github.com/coreos/etcd/pull/8939/files).

xiang90 · 2018-01-06T00:59:24Z

etcdserver/api/v3rpc/watch.go

@@ -26,6 +26,9 @@ import (
 	pb "github.com/coreos/etcd/etcdserver/etcdserverpb"
 	"github.com/coreos/etcd/mvcc"
 	"github.com/coreos/etcd/mvcc/mvccpb"
+
+    "google.golang.org/grpc/codes"


indentation.

spzala · 2018-01-06T01:37:49Z

@gyuho ah, I notice that in your previous PR earlier but thought user interruption/cancellation only impacts 'receive', something that I could test by cancelling watch or lease. But sounds good, I will be covering all. Is there anyway I can test 'send' as well quickly or let's not worry about testing send. Thanks!

spzala · 2018-01-06T02:22:07Z

WIP.

gyuho · 2018-01-06T03:34:36Z

Does this silence the client watch canceling logs when --debug is on? Also squash 3 commits into one? Then LGTM. Thanks!

spzala · 2018-01-06T04:32:48Z

@gyuho thanks! So when --debug is on (./bin/etcd --debug) the following command will produce the message otherwise it won't. I believe that's the expected behavior?
e.g.

 $./bin/etcdctl watch foo
^C
$

And sure I will squash the commits.

xiang90 · 2018-01-06T05:25:42Z

etcdserver/api/v3rpc/util.go

@@ -81,3 +81,9 @@ func togRPCError(err error) error {
 	}
 	return grpcErr
 }
+
+func isClientCtxErr(err error) bool {
+	ev, _ := status.FromError(err)


just to be more defensive, we should check the error against context.DeadlineExceeded and context.Canceled when the fromError fails with error. i am not sure if grpc.send and recv will always return statusError type

Sure. Does it make sense that we pass stream.Context().Err() (or sws.gRPCStream.Context().Err() when needed) to this func and modify the func as below?:

func isClientCtxErr(err error) bool { if err == nil { return false } return err == context.Canceled || err == context.DeadlineExceeded }

i am not sure how exactly the client side context error gets propagated to server side. maybe the stream.Context().Err() only returns the server side context error not the one propagated from the client.

Thanks @xiang90 I see. I was able to run manual tests with using stream.Context().Err() but I will dig more. @gyuho if you have any suggestions please let me know. Thanks!!

Yeah maybe add another parameter to isClientCtxErr function to parse stream.Context errors as well?

Thanks @gyuho !!

xiang90 · 2018-01-07T23:57:34Z

etcdserver/api/v3rpc/util.go

@@ -81,3 +81,12 @@ func togRPCError(err error) error {
 	}
 	return grpcErr
 }
+
+func isClientCtxErr(ctxErr error, err error) bool {
+	if ctxErr != nil {


if ctxErr != nil { return true } ev, err := status.FromError(err) if err != nil { return false } code := ev.Code() return code == codes.Canceled || code == codes.DeadlineExceeded

On ctxErr != nil, return true (instead of ctxErr == context.Canceled || ctxErr == context.DeadlineExceeded) makes sense since context errors seems either context.Canceled or context.DeadlineExceeded

xiang90 · 2018-01-07T23:58:17Z

etcdserver/api/v3rpc/util.go

+	if ctxErr != nil {
+		return ctxErr == context.Canceled || ctxErr == context.DeadlineExceeded
+	}
+	ev, _ := status.FromError(err)


when there is an error, ev will be nil. if we try to get ev.Code on nil, it might panic. see the code above to improve that.

@xiang90 thanks!! Sure, agree. As you mentioned and just looking at status doc, since FromError can return nil we should handle it. I didn't think of it seeing few other places we aren't checking for nil on status.FromError (e.g in client.go and other places) and now it seems like we should, but that's something I will do in separate PR and see if sense that makes sense. Thanks!

(I guess we can check on nil or boolean.)

xiang90 · 2018-01-08T02:24:46Z

Lgtm. Defer to @gyuho

gyuho · 2018-01-08T02:27:39Z

@spzala Let's squash commits into one with commit title etcdserver/api/v3rpc: .... Then LGTM. Thanks!

spzala · 2018-01-08T02:33:06Z

Sounds good. Kids bed time so stepping out but I will be squashing soon. Thanks much @xiang90 @gyuho

The context error with cancel code is typically for user cancellation which should be at debug level. For other error codes we should display a warning. Fixes etcd-io#9085

xiang90 reviewed Jan 5, 2018

View reviewed changes

xiang90 added the backport/v3.3 label Jan 5, 2018

spzala force-pushed the getrevision branch from 96c1c19 to ea0a8ff Compare January 6, 2018 00:42

gyuho reviewed Jan 6, 2018

View reviewed changes

xiang90 reviewed Jan 6, 2018

View reviewed changes

spzala force-pushed the getrevision branch from 102716f to 42388cf Compare January 6, 2018 03:18

xiang90 reviewed Jan 6, 2018

View reviewed changes

xiang90 reviewed Jan 7, 2018

View reviewed changes

spzala force-pushed the getrevision branch from 481832e to c2185e1 Compare January 8, 2018 02:26

gyuho changed the title ~~Log: debug user cancellation and log warning for rest~~ etcdserver/api/v3rpc: debug user cancellation and log warning for rest Jan 8, 2018

etcdserver/api/v3rpc: debug user cancellation and log warning for rest

a66d7c3

The context error with cancel code is typically for user cancellation which should be at debug level. For other error codes we should display a warning. Fixes etcd-io#9085

spzala force-pushed the getrevision branch from c2185e1 to a66d7c3 Compare January 8, 2018 16:05

xiang90 merged commit 44e1f6f into etcd-io:master Jan 8, 2018

spzala mentioned this pull request Jan 19, 2018

gRPC error in etcd v3.2.14 HA environment. #9166

Closed

etcdserver/api/v3rpc: debug user cancellation and log warning for rest #9105

etcdserver/api/v3rpc: debug user cancellation and log warning for rest #9105

Conversation

spzala commented Jan 5, 2018

Contributing guidelines

spzala commented Jan 5, 2018

codecov-io commented Jan 5, 2018 • edited Loading

Codecov Report

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

xiang90 commented Jan 5, 2018 • edited Loading

spzala commented Jan 5, 2018

xiang90 commented Jan 5, 2018

spzala commented Jan 5, 2018

xiang90 commented Jan 5, 2018

spzala commented Jan 5, 2018

spzala commented Jan 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gyuho commented Jan 6, 2018

Choose a reason for hiding this comment

spzala commented Jan 6, 2018

spzala commented Jan 6, 2018

gyuho commented Jan 6, 2018

spzala commented Jan 6, 2018

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

xiang90 Jan 7, 2018 • edited Loading

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

xiang90 commented Jan 8, 2018

gyuho commented Jan 8, 2018

spzala commented Jan 8, 2018

codecov-io commented Jan 5, 2018 •

edited

Loading

xiang90 commented Jan 5, 2018 •

edited

Loading

xiang90 Jan 7, 2018 •

edited

Loading