Grpc-go: Go gRPC Noisy Transport Closing Log

[kushp]

Go Version: go version go1.12.6 darwin/amd64
Go gRPC version: v1.22.0

I run a gRPC server like this:

    opts := []grpc.ServerOption{
        grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(
            grpc_ctxtags.StreamServerInterceptor(),
            grpc_statsd.StreamServerInterceptor(statsdClient, statsdBlacklistedMethods),
            grpc_zap.StreamServerInterceptor(logger),
            grpc_recovery.StreamServerInterceptor(),
            grpc_headers.StreamServerInterceptor(),
        )),
        grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(
            grpc_ctxtags.UnaryServerInterceptor(),
            grpc_statsd.UnaryServerInterceptor(statsdClient, statsdBlacklistedMethods),
            grpc_zap.UnaryServerInterceptor(logger),
            grpc_recovery.UnaryServerInterceptor(),
            grpc_headers.UnaryServerInterceptor(),
        )),
    }
    grpcServer := grpc.NewServer(opts...)

I have some things registered to this server. Then I use gRPC cli to call an RPC.
Every time I do grpc_cli call localhost:9080 Live "" for instance, it says Rpc succeeded with OK status from gRPC cli which is good. But in my service log I see {"level":"info","message":"transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"","system":"grpc","grpc_log":true}. There were previous issues for people seeing this, but they all just said "upgrade Go gRPC" and I did upgrade. I see it's coming from here https://github.com/grpc/grpc-go/blob/08d23162a9a5473a567009b75e9d3b2bc186bedb/internal/transport/controlbuf.go#L430.

Any help will be appreciated :)

I see there is a GRPC_GO_LOG_VERBOSITY_LEVEL which I can set to 1 to remove the log, but this does not work for me because i replace the logger with grpc zap and that does not respect the GRPC_GO_LOG_VERBOSITY_LEVEL.

I'm wondering if we can by default disable this log to all users if it is meant to happen every time you make a gRPC call (or make it a debug level log instead of info) or if I'm doing something wrong and it's not suppose to happen all the time.

[menghanl]

This log happens when the underlying connection is closed (for many potential reasons). So it could be useful sometimes for debugging.

In your case, every time grpc_cli is called, it creates a new connection to the server, sends the RPC, and kills the connection. So it triggers this log a lot.
If your connections are stable, you shouldn't see this log very often.

I agree it can be spamming, and that's why we put it as info log at verbose level 2 (we don't have debug level logs).

---

On the logging library. I would think it's reasonable to ask for verbose level support in grpc zap (it's still using v1 logger interface, verbose is part of v2).
Also, it should be pretty easy to wrap grpc zap into a v2 interface and add support for verbose yourself.

[kushp]

Thank you for your response @menghanl, this makes sense to me. I think the default verbose level is 0 when I take away the grpc_zap stuff it uses that and logging isn't spammy. I can close this question. I opened this instead https://github.com/grpc-ecosystem/go-grpc-middleware/issues/219. If you're also maintainer at go grpc middleware let me know and I can take on this work.

[menghanl]

@kushp Thanks for filing the issue. But grpc middleware is not maintained by us.

[kush-patel-hs]

No worries, I got in touch with a maintainer of grpc middleware @menghanl ! I have this open PR https://github.com/grpc-ecosystem/go-grpc-middleware/pull/221 which should fix my problem as it will implement V2 logger interface and adhere to verbosity etc.