etcdserver: add grpc interceptor to log info on incoming request to etcdserver #9990

jingyih · 2018-08-09T00:07:48Z

This is to improve debuggability of etcd v3. Added a grpc interceptor to log information on incoming requests to etcdserver.

The log output includes:

request starting time,
request handling latency,
remote client info,
request key count,
request byte size,
response key count,
response byte size,
request content (with value field redacted).

Example log output:

./etcdctl put foo bar
{"level":"debug","ts":1533772428.8998141,"caller":"v3rpc/interceptor.go:168","msg":"request stats","start time":1533772428.89934,"time spent":0.000403816,"remote":"127.0.0.1:46300","response type":"/etcdserverpb.KV/Put","request count":1,"request size":10,"response count":0,"response size":28,"request content":"key:\"foo\" value_size:3 "}

Logging is enable by --debug flag.

Fixes #9989

cc @jpbetz @gyuho

gyuho · 2018-08-09T00:16:15Z

I don't see anywhere we use https://godoc.org/google.golang.org/grpc/peer#NewContext? Is peer information automatically embedded by middleware?

jingyih · 2018-08-09T01:21:16Z

@gyuho I think the peer information is been added during grpc remote call? Here is what I found:

./vendor/google.golang.org/grpc/transport/http2_server.go:	s.ctx = peer.NewContext(s.ctx, pr)
./vendor/google.golang.org/grpc/transport/handler_server.go:	s.ctx = peer.NewContext(ctx, pr)
./vendor/google.golang.org/grpc/transport/http2_client.go:	ctx = peer.NewContext(ctx, t.getPeer())

gyuho · 2018-08-09T14:03:53Z

@jingyih I see. Then, can you document those as a comment? Also, CIs are failing.

jingyih · 2018-08-09T21:18:23Z

@gyuho Sounds good! I will add the comment.

jingyih · 2018-08-09T21:21:38Z

@gyuho Regarding the failed CIs. Except for one go format issue, others seems to be caused by missing the grpc-middleware package in vendor. I saw there is scripts/updatedep.sh. Should I run this? Is there instructions on how to update the vendor? Thanks!

gyuho · 2018-08-09T21:27:47Z

@jingyih Yes, ./scripts/updatedep.sh [dependency-import-path-goes-here] should work.

jingyih · 2018-08-10T00:37:05Z

@gyuho After I ran updatedep.sh, I observed two changes to the Gopkg.lock file.

the missing package in CI was added. (i.e., go-grpc-middleware)
grpc package was downgraded from v1.14.0 to v1.13.0

I am aware of the PR from you which upgraded gprc to v1.14.0 recently, so I did some investigation on the version downgrade. In master branch, I see that the grpc version is still v1.13.0 under folder https://github.com/coreos/etcd/tree/master/vendor/google.golang.org/

Is this consistent with the Gopkg.lock file which says the grpc version is v1.14.0?

cc @jpbetz

gyuho · 2018-08-10T01:09:03Z

@jingyih Ah, previous godep run seemed to fail on that. Let me fix it shortly, to bump up gRPC to v1.14.

jingyih · 2018-08-10T01:21:53Z

@gyuho

I noticed that grpc moved transport package from their root folder to internal, in release 1.14.0 (https://github.com/grpc/grpc-go/releases/tag/v1.14.0)

On the other hand, etcd does have dependency on "google.golang.org/grpc/transport". (in ./clientv3/integration/server_shutdown_test.go)

Not sure if this is the reason grpc is v1.13.0 in etcd vendor folder.

gyuho · 2018-08-10T13:37:10Z

etcdserver/api/v3rpc/interceptor.go

+	}
+	var responseType string = info.FullMethod
+	var reqCount, respCount int64 = 0, 0
+	var reqSize, respSize int = 0, 0


No need = 0, 0?

Agreed. They are zero-valued by default. Thanks!

gyuho · 2018-08-10T13:37:46Z

@jingyih Good catch!

Could you rebase from master? Should be fixed by #9994.

etcd server To improve debuggability of etcd v3. Added a grpc interceptor to log info on incoming requests to etcd server. The log output includes remote client info, request content (with value field redacted), request handling latency, response size, etc. Uses zap logger if available, otherwise uses capnslog. Also did some clean up on the chaining of grpc interceptors on server side.

Rebased to master PR etcd-io#9994. Fixed a Go format issue in v3rpc/interceptor.go. Updated vendor to include go-grpc-middleware.

jpbetz · 2018-08-10T22:25:04Z

LGTM, I'll wait on @gyuho's approval for this one since I was involved in pre-review.

gyuho · 2018-08-10T23:13:20Z

etcdserver/api/v3rpc/interceptor.go

@@ -90,7 +210,8 @@ func newStreamInterceptor(s *etcdserver.EtcdServer) grpc.StreamServerInterceptor
 			}
 		}

-		return prometheus.StreamServerInterceptor(srv, ss, info, handler)
+		err := handler(srv, ss)
+		return err


We can just simply return handler(srv, ss)

sure I will make the change.

gyuho · 2018-08-10T23:13:40Z

@jingyih Just small nits, then should be good to merge. Thanks!

Code clean up in interceptor.go

gyuho

lgtm thanks @jingyih !

…-origin-release-3.3 Automated cherry pick of #9990

…-origin-release-3.2-1534373481 etcdserver: cherry pick of #9990 to release-3.2

…lease-3.1 etcdserver: cherry pick of #9990 to release 3.1

jingyih · 2018-08-27T17:55:55Z

/cc @wenjiaswe

CHANGELOG-3.3: update from #9990

vivekpatani · 2021-06-12T16:59:49Z

etcdserver/api/v3rpc/interceptor.go

+	case *pb.PutResponse:
+		_req, ok := req.(*pb.PutRequest)
+		if ok {
+			reqCount = 1


This count is 1 for PUTs, but 0 for other types of requests and not set for TXN, what does this represent? Just trying to understand. Thanks. @jingyih

gyuho added the Release-Note label Aug 9, 2018

gyuho reviewed Aug 10, 2018

View reviewed changes

jingyih force-pushed the dev_workload_analysis_tool branch from b898479 to ca20f01 Compare August 10, 2018 18:19

vendor: add go-grpc-middleware

3066294

Rebased to master PR etcd-io#9994. Fixed a Go format issue in v3rpc/interceptor.go. Updated vendor to include go-grpc-middleware.

jingyih force-pushed the dev_workload_analysis_tool branch from ca20f01 to 3066294 Compare August 10, 2018 20:17

gyuho reviewed Aug 10, 2018

View reviewed changes

etcdserver: code clean up

368010d

Code clean up in interceptor.go

gyuho approved these changes Aug 11, 2018

View reviewed changes

gyuho merged commit 3a03774 into etcd-io:master Aug 11, 2018

This was referenced Aug 14, 2018

Automated cherry pick of #9990 #10003

Closed

etcdserver: automated cherry pick of #9990 to release-3.3 #10004

Merged

gyuho added a commit that referenced this pull request Aug 15, 2018

Merge pull request #10004 from jingyih/automated-cherry-pick-of-#9990…

f8fc923

…-origin-release-3.3 Automated cherry pick of #9990

jingyih mentioned this pull request Aug 18, 2018

etcdserver: cherry pick of #9990 to release-3.2 #10025

Merged

hexfusion mentioned this pull request Aug 18, 2018

etcdserver: cherry-pick #9861 to release-3.3 #10027

Merged

jpbetz added a commit that referenced this pull request Aug 20, 2018

Merge pull request #10025 from jingyih/automated-cherry-pick-of-#9990…

73b1a2b

…-origin-release-3.2-1534373481 etcdserver: cherry pick of #9990 to release-3.2

jingyih mentioned this pull request Aug 20, 2018

etcdserver: cherry pick of #9990 to release 3.1 #10030

Merged

jpbetz added a commit that referenced this pull request Aug 20, 2018

Merge pull request #10030 from jingyih/cherry-pick-of-#9990-origin-re…

2c616b0

…lease-3.1 etcdserver: cherry pick of #9990 to release 3.1

jingyih added a commit to jingyih/etcd that referenced this pull request Sep 29, 2018

CHANGELOG-3.3: update from etcd-io#9990

30fbcf5

jingyih mentioned this pull request Sep 29, 2018

CHANGELOG-3.3: update from #9990 #10138

Merged

jingyih added a commit that referenced this pull request Sep 29, 2018

Merge pull request #10138 from jingyih/update_changelog_3p3_from_pr9990

60fd69a

CHANGELOG-3.3: update from #9990

jingyih mentioned this pull request Sep 29, 2018

Auditing changes to key/value in etcd #5019

Closed

jingyih deleted the dev_workload_analysis_tool branch September 7, 2019 07:08

jingyih mentioned this pull request Jan 21, 2020

Why can't we have audit logs？ #11551

Closed

vivekpatani reviewed Jun 12, 2021

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

etcdserver: add grpc interceptor to log info on incoming request to etcdserver #9990

etcdserver: add grpc interceptor to log info on incoming request to etcdserver #9990

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 9, 2018

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 10, 2018 •

edited

Loading

gyuho commented Aug 10, 2018

jingyih commented Aug 10, 2018

gyuho Aug 10, 2018

jingyih Aug 10, 2018

gyuho commented Aug 10, 2018

jpbetz commented Aug 10, 2018

gyuho Aug 10, 2018

jingyih Aug 10, 2018

gyuho commented Aug 10, 2018

gyuho left a comment

jingyih commented Aug 27, 2018

vivekpatani Jun 12, 2021

etcdserver: add grpc interceptor to log info on incoming request to etcdserver #9990

etcdserver: add grpc interceptor to log info on incoming request to etcdserver #9990

Conversation

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 9, 2018

jingyih commented Aug 9, 2018

gyuho commented Aug 9, 2018

jingyih commented Aug 10, 2018 • edited Loading

gyuho commented Aug 10, 2018

jingyih commented Aug 10, 2018

gyuho Aug 10, 2018

Choose a reason for hiding this comment

jingyih Aug 10, 2018

Choose a reason for hiding this comment

gyuho commented Aug 10, 2018

jpbetz commented Aug 10, 2018

gyuho Aug 10, 2018

Choose a reason for hiding this comment

jingyih Aug 10, 2018

Choose a reason for hiding this comment

gyuho commented Aug 10, 2018

gyuho left a comment

Choose a reason for hiding this comment

jingyih commented Aug 27, 2018

vivekpatani Jun 12, 2021

Choose a reason for hiding this comment

jingyih commented Aug 10, 2018 •

edited

Loading