deps: upgrade grpc-ecosystem/go-grpc-middleware to v2

[marefr]

Follow up from #17884. Upgrades github.com/grpc-ecosystem/go-grpc-middleware to v2.

Ref #17883

From #17884 (review):

Expect this code to land in some logutil package. We have one for client client/pkg/logutil. I expect it's in client due to legacy, we could move it to pkg/logutil

New GrpcLoggerInterceptor function (copied from here) added to existing client/pkg/logutil package. Suggest moving to pkg/logutil in a separate PR. Let me know what you think.

Regarding tests/framework/integration/settable_logger.go I copied that from here. I did consider copying the tests as well, but wasn't sure it made sense to have unit tests in the framework/integration package. Then I thought, maybe an internal package would make sense, but wasn't sure that would fit in the framework/integration package either. I left it in the integration package for now, but did change to make it non-exportable. Let me know if you have a better idea here.

[k8s-ci-robot]

Hi @marefr. Thanks for your PR.

I'm waiting for a etcd-io member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[ahrtr]

/ok-to-test

[ahrtr]

It seems that the grpc-proxy changes the behaviour. The existing main branch could print the payload, but this PR doesn't print the payload anymore.

Main branch

./etcdctl put greeting "Hello, world"
{"level":"info","ts":"2022-07-29T10:14:41.890+0800","caller":"zap/payload_interceptors.go:131","msg":"server request payload logged as grpc.request.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","peer.address":"127.0.0.1:54276","grpc.request.content":{"msg":{"key":"Z3JlZXRpbmc=","value":"SGVsbG8sIHdvcmxk"}}}
{"level":"info","ts":"2022-07-29T10:14:41.891+0800","caller":"zap/payload_interceptors.go:131","msg":"server response payload logged as grpc.response.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","peer.address":"127.0.0.1:54276","grpc.response.content":{"msg":{"header":{"clusterId":"12526192129151561082","memberId":"3877455311180318034","revision":"2","raftTerm":"2"}}}}

./etcdctl get greeting
{"level":"info","ts":"2022-07-29T10:16:24.250+0800","caller":"zap/payload_interceptors.go:131","msg":"server request payload logged as grpc.request.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","peer.address":"127.0.0.1:54297","grpc.request.content":{"msg":{"key":"Z3JlZXRpbmc="}}}
{"level":"info","ts":"2022-07-29T10:16:24.251+0800","caller":"zap/payload_interceptors.go:131","msg":"server response payload logged as grpc.response.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","peer.address":"127.0.0.1:54297","grpc.response.content":{"msg":{"header":{"clusterId":"12526192129151561082","memberId":"3877455311180318034","revision":"2","raftTerm":"2"},"kvs":[{"key":"Z3JlZXRpbmc=","createRevision":"2","modRevision":"2","version":"1","value":"SGVsbG8sIHdvcmxk"}],"count":"1"}}}

This PR

$ ./bin/etcdctl put greeting "Hello, world"
{"level":"info","ts":"2024-05-01T10:41:29.292659+0100","caller":"logging/logging.go:202","msg":"started call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:51150","grpc.start_time":"2024-05-01T10:41:29+01:00","grpc.request.deadline":"2024-05-01T10:41:34+01:00","grpc.time_ms":"0.016"}
{"level":"info","ts":"2024-05-01T10:41:29.299058+0100","caller":"logging/logging.go:202","msg":"finished call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:51150","grpc.start_time":"2024-05-01T10:41:29+01:00","grpc.request.deadline":"2024-05-01T10:41:34+01:00","grpc.code":"OK","grpc.time_ms":"6.421"}

$ ./bin/etcdctl get greeting
{"level":"info","ts":"2024-05-01T10:41:41.317574+0100","caller":"logging/logging.go:202","msg":"started call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:51158","grpc.start_time":"2024-05-01T10:41:41+01:00","grpc.request.deadline":"2024-05-01T10:41:46+01:00","grpc.time_ms":"0.014"}
{"level":"info","ts":"2024-05-01T10:41:41.318452+0100","caller":"logging/logging.go:202","msg":"finished call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:51158","grpc.start_time":"2024-05-01T10:41:41+01:00","grpc.request.deadline":"2024-05-01T10:41:46+01:00","grpc.code":"OK","grpc.time_ms":"0.922"}

[ahrtr]

Refer to #14266 (comment)

[ahrtr]

We have already upgraded to grpc-ecosystem/go-grpc-middleware/v2 in this PR, I am a little concerned why we still need to copy code from grpc-ecosystem/go-grpc-middleware v1 ? Is it possible to do it in consistent & v2 style?

Also link to the original PR which introduced the var grpc_logger grpc_logsettable.SettableLoggerV2 in integration test. #12781

[marefr]

logsettable package was removed in v2 so I opted to copy from v1 in lack of alternative.

[ahrtr]

cc @stefanmonkey who is the author of the PR #14266

[marefr]

It seems that the grpc-proxy changes the behaviour. The existing main branch could print the payload, but this PR doesn't print the payload anymore.

Main branch

./etcdctl put greeting "Hello, world"
{"level":"info","ts":"2022-07-29T10:14:41.890+0800","caller":"zap/payload_interceptors.go:131","msg":"server request payload logged as grpc.request.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","peer.address":"127.0.0.1:54276","grpc.request.content":{"msg":{"key":"Z3JlZXRpbmc=","value":"SGVsbG8sIHdvcmxk"}}}
{"level":"info","ts":"2022-07-29T10:14:41.891+0800","caller":"zap/payload_interceptors.go:131","msg":"server response payload logged as grpc.response.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","peer.address":"127.0.0.1:54276","grpc.response.content":{"msg":{"header":{"clusterId":"12526192129151561082","memberId":"3877455311180318034","revision":"2","raftTerm":"2"}}}}

./etcdctl get greeting
{"level":"info","ts":"2022-07-29T10:16:24.250+0800","caller":"zap/payload_interceptors.go:131","msg":"server request payload logged as grpc.request.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","peer.address":"127.0.0.1:54297","grpc.request.content":{"msg":{"key":"Z3JlZXRpbmc="}}}
{"level":"info","ts":"2022-07-29T10:16:24.251+0800","caller":"zap/payload_interceptors.go:131","msg":"server response payload logged as grpc.response.content field","system":"grpc","span.kind":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","peer.address":"127.0.0.1:54297","grpc.response.content":{"msg":{"header":{"clusterId":"12526192129151561082","memberId":"3877455311180318034","revision":"2","raftTerm":"2"},"kvs":[{"key":"Z3JlZXRpbmc=","createRevision":"2","modRevision":"2","version":"1","value":"SGVsbG8sIHdvcmxk"}],"count":"1"}}}

This PR

$ ./bin/etcdctl put greeting "Hello, world"
{"level":"info","ts":"2024-05-01T10:41:29.292659+0100","caller":"logging/logging.go:202","msg":"started call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:51150","grpc.start_time":"2024-05-01T10:41:29+01:00","grpc.request.deadline":"2024-05-01T10:41:34+01:00","grpc.time_ms":"0.016"}
{"level":"info","ts":"2024-05-01T10:41:29.299058+0100","caller":"logging/logging.go:202","msg":"finished call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:51150","grpc.start_time":"2024-05-01T10:41:29+01:00","grpc.request.deadline":"2024-05-01T10:41:34+01:00","grpc.code":"OK","grpc.time_ms":"6.421"}

$ ./bin/etcdctl get greeting
{"level":"info","ts":"2024-05-01T10:41:41.317574+0100","caller":"logging/logging.go:202","msg":"started call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:51158","grpc.start_time":"2024-05-01T10:41:41+01:00","grpc.request.deadline":"2024-05-01T10:41:46+01:00","grpc.time_ms":"0.014"}
{"level":"info","ts":"2024-05-01T10:41:41.318452+0100","caller":"logging/logging.go:202","msg":"finished call","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:51158","grpc.start_time":"2024-05-01T10:41:41+01:00","grpc.request.deadline":"2024-05-01T10:41:46+01:00","grpc.code":"OK","grpc.time_ms":"0.922"}

Thanks for spotting this. Changed to use the payload received/sent events instead of start/finish call events for the logger interceptor. However, it doesn't look promising 😢

./etcdctl put greeting "Hello, world"
{"level":"error","ts":"2024-05-01T19:10:35.262291+0200","caller":"logging/logging.go:202","msg":"payload is not a google.golang.org/protobuf/proto.Message; programmatic error?","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:64573","grpc.start_time":"2024-05-01T19:10:35+02:00","grpc.request.deadline":"2024-05-01T19:10:40+02:00","grpc.request.type":"*etcdserverpb.PutRequest","stacktrace":"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/logging.go:202\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostMsgReceive\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/interceptors.go:111\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.UnaryServerInterceptor.UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/server.go:21\ngoogle.golang.org/grpc.getChainUnaryHandler.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1186\ngithub.com/grpc-ecosystem/go-grpc-prometheus.init.(*ServerMetrics).UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1177\ngo.etcd.io/etcd/api/v3/etcdserverpb._KV_Put_Handler\n\tgo.etcd.io/etcd/api/v3@v3.6.0-alpha.0/etcdserverpb/rpc.pb.go:6640\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1369\ngoogle.golang.org/grpc.(*Server).handleStream\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1780\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1019"}
{"level":"error","ts":"2024-05-01T19:10:35.266355+0200","caller":"logging/logging.go:202","msg":"payload is not a google.golang.org/protobuf/proto.Message; programmatic error?","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Put","grpc.method_type":"unary","peer.address":"127.0.0.1:64573","grpc.start_time":"2024-05-01T19:10:35+02:00","grpc.request.deadline":"2024-05-01T19:10:40+02:00","grpc.response.type":"*etcdserverpb.PutResponse","stacktrace":"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/logging.go:202\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostMsgSend\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/interceptors.go:79\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.UnaryServerInterceptor.UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/server.go:23\ngoogle.golang.org/grpc.getChainUnaryHandler.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1186\ngithub.com/grpc-ecosystem/go-grpc-prometheus.init.(*ServerMetrics).UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1177\ngo.etcd.io/etcd/api/v3/etcdserverpb._KV_Put_Handler\n\tgo.etcd.io/etcd/api/v3@v3.6.0-alpha.0/etcdserverpb/rpc.pb.go:6640\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1369\ngoogle.golang.org/grpc.(*Server).handleStream\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1780\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1019"}

./etcdctl get greeting
{"level":"error","ts":"2024-05-01T19:10:50.119177+0200","caller":"logging/logging.go:202","msg":"payload is not a google.golang.org/protobuf/proto.Message; programmatic error?","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:64606","grpc.start_time":"2024-05-01T19:10:50+02:00","grpc.request.deadline":"2024-05-01T19:10:55+02:00","grpc.request.type":"*etcdserverpb.RangeRequest","stacktrace":"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/logging.go:202\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostMsgReceive\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/interceptors.go:111\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.UnaryServerInterceptor.UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/server.go:21\ngoogle.golang.org/grpc.getChainUnaryHandler.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1186\ngithub.com/grpc-ecosystem/go-grpc-prometheus.init.(*ServerMetrics).UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1177\ngo.etcd.io/etcd/api/v3/etcdserverpb._KV_Range_Handler\n\tgo.etcd.io/etcd/api/v3@v3.6.0-alpha.0/etcdserverpb/rpc.pb.go:6622\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1369\ngoogle.golang.org/grpc.(*Server).handleStream\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1780\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1019"}
{"level":"error","ts":"2024-05-01T19:10:50.120672+0200","caller":"logging/logging.go:202","msg":"payload is not a google.golang.org/protobuf/proto.Message; programmatic error?","protocol":"grpc","grpc.component":"server","grpc.service":"etcdserverpb.KV","grpc.method":"Range","grpc.method_type":"unary","peer.address":"127.0.0.1:64606","grpc.start_time":"2024-05-01T19:10:50+02:00","grpc.request.deadline":"2024-05-01T19:10:55+02:00","grpc.response.type":"*etcdserverpb.RangeResponse","stacktrace":"github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.LoggerFunc.Log\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/logging.go:202\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.(*reporter).PostMsgSend\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/logging/interceptors.go:79\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/logging.UnaryServerInterceptor.UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/server.go:23\ngoogle.golang.org/grpc.getChainUnaryHandler.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1186\ngithub.com/grpc-ecosystem/go-grpc-prometheus.init.(*ServerMetrics).UnaryServerInterceptor.func2\n\tgithub.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1177\ngo.etcd.io/etcd/api/v3/etcdserverpb._KV_Range_Handler\n\tgo.etcd.io/etcd/api/v3@v3.6.0-alpha.0/etcdserverpb/rpc.pb.go:6622\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1369\ngoogle.golang.org/grpc.(*Server).handleStream\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1780\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1\n\tgoogle.golang.org/grpc@v1.63.2/server.go:1019"}

The error payload is not a google.golang.org/protobuf/proto.Message indicates that google.golang.org/protobuf is required and etcd are dependent on the superseded https://github.com/golang/protobuf. This leaves us with 5 options as I see it

1. Migrate to google.golang.org/protobuf. You're dependent on the deprecated https://github.com/gogo/protobuf and the protoc-gen-gofast tool for generate the protobuf messages. I'm guessing that tool adds imports to "github.com/golang/protobuf/proto". Seems very hard to me and not a short-term option.
2. Re-implement parts of the grpc logging package in etcd. Especially, these type casts to target github.com/golang/protobuf instead.
3. Similar to 2), but propose go-grpc-middleware change to allow overriding what protobuf package to target so that etcd doesn't have to maintain custom grpc logger interceptor code.
4. Only remove usage of grpc-ecosystem/go-grpc-middleware ChainUnaryInterceptor / ChainStreamInterceptor since provided by gRPC now and leave it there.
5. Give up and close this PR

Thoughts?

[marefr]

/retest

[ahrtr]

Thanks for your effort so far.

The error payload is not a google.golang.org/protobuf/proto.Message indicates that google.golang.org/protobuf is required and etcd are dependent on the superseded https://github.com/golang/protobuf. This leaves us with 5 options as I see it

1. Migrate to google.golang.org/protobuf. You're dependent on the deprecated https://github.com/gogo/protobuf and the protoc-gen-gofast tool for generate the protobuf messages. I'm guessing that tool adds imports to "github.com/golang/protobuf/proto". Seems very hard to me and not a short-term option.

Yes, it's true and the option 1 is definitely my preference. It's one of the tech debts which etcd has. There is an issue #14533 to track the effort. But unfortunately, I do not get time to work on it. No people work on it either. It would be great If you are interested and have bandwidth to work on it, and I am happy to provide whatever help.

4. Only remove usage of grpc-ecosystem/go-grpc-middleware ChainUnaryInterceptor / ChainStreamInterceptor since provided by gRPC now and leave it there.

Please feel free to raise a separate PR to resolve it. I think it can be approved & merged soon.

[ahrtr]

FYI. We faced similar issue previously when we upgraded grpc-gateway from v1 to v2
#16595

[marefr]

Yes, it's true and the option 1 is definitely my preference. It's one of the tech debts which etcd has. There is an issue #14533 to track the effort. But unfortunately, I do not get time to work on it. No people work on it either. It would be great If you are interested and have bandwidth to work on it, and I am happy to provide whatever help.

Understood and thanks for the pointer. Not sure I have the etcd knowledge needed nor bandwidth I'm afraid. Quite hard to see how much changes and possibly breaking changes this might require. I do have quite good understanding of protobuf so if I get time I might try and upgrade and see what changes/breaks and report back in the issue. Might help to break up the work needed? Or have anyone already tried this already perhaps? It didn't seem like it in the issue.

Please feel free to raise a separate PR to resolve it. I think it can be approved & merged soon.

#17922

[marefr]

Based on the discussions closing this for now. Opened #17922 and lets continue the discussions in #14533. Thanks