ErrConnClosing sometimes bubbles up as an rpcError

[tamird]

I see stuff like this bubble up in my logs:

E0205 18:18:33.157609 40850 gossip/client.go:267  rpc error: code = 13 desc = "transport is closing"

Normally I'd expect this not to appear, since I deliberately do not log ErrConnClosing, and the definition of ErrConnClosing is the only instance of "transport is closing" in grpc.

[iamqizhao]

This is typically because you perform an rpc after closing ClientConn. I could help if you provide more info. Your code probably has a race.

[tamird]

You're probably right, but that's to be expected; I have created the ClientConn with a context.WithCancel, then cancelled the context while another goroutine tried to Send() on the ClientConn. This use is race-free in the race detector sense, but it will produce this error, which is just needlessly hard to compare to ErrConnClosing.

[iamqizhao]

Yes, it is expected. What I am missing here is that why it bothers you.

[tamird]

My code is attempting not to log these expected errors:

err := stream.Send(reply)
if err != nil {
    if !grpcutil.IsClosedConnection(err) {
        log.Error(err)
    }
    return
}

where

// IsClosedConnection returns true if err is an error produced by gRPC on closed connections.
func IsClosedConnection(err error) bool {
    if err == transport.ErrConnClosing {
        return true
    }
    if grpc.Code(err) == codes.Canceled {
        return true
    }
    if streamErr, ok := err.(transport.StreamError); ok && streamErr.Code == codes.Canceled {
        return true
    }
    return false
}

So the wrapping in rpcError is causing me to log an error where I do not expect to log one.

[iamqizhao]

I would say this is incorrect. I do not know the purpose you want to do this. But transport is a private package which should only be used by grpc package (yes and some proxy which does not need to know the upper level grpc semantics).

[tamird]

It's hard to give a small self-contained snippet, but the usage is here: cockroachdb/cockroach#4080 - the last commit adds this logging suppression.

[iamqizhao]

I would guess your definition of "uninteresting" is probably problematic. What is your intention? What errors do you want to filter out?

[tamird]

As far as I can tell, there are two categories:

• RPC method returns before a call to stream.{Send,Recv} - this can happen in a bidirectional stream when the two directions are being processed asynchronously. we want to ignore this error.
• context is cancelled before a call to stream.{Send,Recv}. we want to ignore this error.

[iamqizhao]

This sounds like what you want to do instead of why you want to do. Why do you want to ignore these two types of errors for logging?

[tamird]

These errors only occur during shutdown; our bidirectional streaming RPCs never otherwise terminate.

[hsaliak]

Some of the levelled logging that is being implemented by @menghanl in #922 should help here.

[tamird]

This was fixed by the combination of b507112 and a3592bd.