client fails annoyingly with lots of log messages when server does not speak grpc about grpc-go

[schmohlio]

is there any update on this? This problem really floods logs when running on GCE. setting the logger seems to provide an initial fix, but feels wrong

[menghanl]

We are working on improving the logging system, #922 is the first step.

[iamqizhao]

On Mon, Mar 16, 2015 at 6:38 PM, jellevandenhooff [email protected]
wrote:

I am running "go version go1.4.1 darwin/amd64". I accidentally pointed a
grpc client at an address that didn't speak grpc. Afterwards, grpc printed
a lot of messages in the log that were not helpful at best and distracting
at worst. I would prefer grpc to a) not generate as many errors, perhaps
with some back-off mechanism, and b) not print as many errors.

Specifically, my terminal filled with hundreds of lines of the form

2015/03/16 21:08:01 transport: http2Client.notifyError got notified that
the client transport was broken unexpected EOF.
2015/03/16 21:08:01 transport: http2Client.notifyError got notified that
the client transport was broken unexpected EOF.
2015/03/16 21:08:01 transport: http2Client.notifyError got notified that
the client transport was broken unexpected EOF.
2015/03/16 21:08:01 transport: http2Client.notifyError got notified that
the client transport was broken unexpected EOF.
2015/03/16 21:08:01 transport: http2Client.notifyError got notified that
the client transport was broken unexpected EOF.

I tried sticking in a "c.failFast = true" in grpc.Invoke, but that did not
help.

I had got another user request which complained that there was no log
messages when the transport sees some error triggering reconnect. So I
added this log which seems spam you now. :) Let me see if there is a way I
can win in both worlds.

—
Reply to this email directly or view it on GitHub
#120.

[jellevandenhooff]

Ah -- I guess the messages themselves might by only a symptom of the underlying problem. I don't know if instantaneous reconnecting is desired behavior, but if it is not, then adding some back-off would probably also make me happy :)

Thanks!

[iamqizhao]

Exponential back-off is already there (https://github.com/grpc/grpc-go/blob/master/clientconn.go#L164). You actually hit a different case: your connect actually succeeded because that port is listening but when you sent the first rpc it got rejected by the peer because the peer does not speak grpc. Therefore, you already hit the initial reconnect interval.

[jellevandenhooff]

How do you feel about moving the exponential back-off into clientConn so it also backs-off if a server is crashing or misbehaving? I could try and see what it looks like if you like that idea.

[yinhm]

I was thinking can we reconnect a little bit of more aggressive, I mean, I need to restart client mostly of the time when I restart server doesn't feels right. It killing my productivity.

Maybe reconnect if there is new rpc calls in client? Maybe just a little of aggressive, my server has no complain of that. What I want is thought of like zeromq or nanomsg, you don't need to care if server was going down, you just send messages.

[mauaht]

Got the same high volume of error messages under the following scenario:

• Set up generic TCP listener which accepts and closes connections
• Send a request to server using the grpc hello world tutorial

It looks like there is an infinite loop in the Invoke function in /grpc/call.go as follows:

• Invoke creates callInfo with callInfo.failFast=false at line 109
• If sendRequest() in line 169 fails with transport.ConnectionError a subsequent continue jumps to loop start at line 143
• If recvResponse() in line 181 fails with transport.ConnectionError a subsequent continue jumps to loop start at line 143
• Loop does not exit because callInfo.failFast=false blocks error handling at line 150

Setting callInfo.failFast=true aborts the loop at line 143 and prevents the infinite loop.

In this case where the server explicitely closes the connection, because it does not recognise the grpc protocol, the client should not attempt retry.
There may be other transport.ConnectionError cases for which limited retries are appropriate, but unbounded retries are not a good idea.

The following test code reproduces the above scenario

import (
    "fmt"
    "testing"
    "net"
    "golang.org/x/net/context"
    "google.golang.org/grpc"  
    demo "google.golang.org/grpc/examples/helloworld/helloworld"
)

const hw_addr = "127.0.0.0:50000" 

func TestGrpcReject(t *testing.T) {
    // Create a simple server that just closes connections  
    lis, err := net.Listen("tcp", hw_port)
    if err != nil { fmt.Printf("Listener not started: %v\n", err); return }

    go func() {
        for {
            conn, _ := lis.Accept() 
            fmt.Printf("Server closing connection\n")
            conn.Close()
        }
    }()     

    // Set up client and send request to server
    conn, err := grpc.Dial(hw_address, grpc.WithInsecure())
    client := demo.NewGreeterClient(conn)
    client.SayHello(context.Background(), &demo.HelloRequest{Name: "World"})
}

[artushin]

I also felt this was extremely annoying in a dev environment (I have multiple services connecting to a non-critical grpc service and they would cumulatively spit out over 10k log lines in 5 seconds if I turned that service off), so I just replace the grpclog Logger with grpclog.SetLogger(log.New(ioutil.Discard, "", 0)) when in dev.

[iamqizhao]

If you replace it with glogger (https://github.com/grpc/grpc-go/blob/master/grpclog/glogger/glogger.go), all the logs will go to some files instead of stderr unless you configure it explicitly.

[gm42]

I am experiencing same issue and using grpclog.SetLogger. However, as I see it the problem is that there is no context about the error: if I am using different gRPC services I will never know by reading this log message which one is specifically the failing service.

Would it be possible to add to this log message more context e.g. the hostname or service name?

[c4milo]

It would be very nice if the underlined backoff mechanism covers this case as well.

[jellevandenhooff]

While I appreciate #922, the many log messages are a symptom of many failed connection attempts. I think it'd be worthwhile also reducing connection frequency, because even if we're not spewing logs, we're still hammering some poor unsuspecting service.

[c4milo]

I was going to mention @jellevandenhooff's observation too, I thought there was some sort of exponential backoff involved when reconnecting.

[menghanl]

Can you share more information about your program? Like what the error you got was and what server were you connecting to? What we want to know is the root cause of the connection error.

We have backoff mechanism if the connection can't be established at the first place.
One possible situation where the flood can happen is that the connection is established successfully, and disconnects immediately after that. We should do something (backoff or even stop retrying) depending on the reason.

[jellevandenhooff]

The root cause of the error is exactly as you described, and a backoff as you propose is the solution. My PR from last year sketched out an approach for implementing that, but with all the changes to grpc, doesn't quite merge anymore.

[menghanl]

The root cause of the error is exactly as you described

I assume by this you mean "connection is established successfully, and disconnects immediately after that."
Then what is the reason for this to happen in your case? (The server is a misbehavior server? or a non-gRPC server?)

[c4milo]

@menghanl in my case the server did not have properly setup the certificate.

[jellevandenhooff]

closing in favor of #954