wrong error logging

[minaevmike]

Please answer these questions before submitting your issue.

What version of gRPC are you using?

master

What version of Go are you using (go version)?

go version go1.10 linux/amd64

What operating system (Linux, Windows, …) and version?

linux

What did you do?

i have an reflection client and server. i make a simple request

        conn, err := grpc.Dial(cfg.Endpoint, opts...)
	if err != nil {
		return err
	}

	cl := ref.NewServerReflectionClient(conn)

	stream, err := cl.ServerReflectionInfo(context.Background())
	if err != nil {
		return err
	}
	h, _ := os.Hostname()
	err = stream.Send(&ref.ServerReflectionRequest{
		Host:           h,
		MessageRequest: &ref.ServerReflectionRequest_ListServices{ListServices: ""},
	})
	if err != nil {
		return err
	}

	_, err = stream.Recv()
	if err != nil {
		return err
	}
	stream.CloseSend()
	return conn.Close()
}

on server i have error log like

 2018-05-10T16:38:05.694+0300    ERROR    grpclog/grpclog.go:75    transport: loopyWriter.run returning. Err: connection error: desc = "transport is closing"

this message would be print even if err is nil. https://github.com/grpc/grpc-go/blob/master/transport/controlbuf.go#L371
Anyway i would to ask - is it a proper way to close connection?

[dfawley]

this message would be print even if err is nil. /transport/controlbuf.go@master#L371

This function (run) is an infinite loop, and does not return unless there is a non-nil err.

That said, it's not useful to log (especially as an error) things that are normal termination conditions. We should update this accordingly.

What you've done looks mostly OK. I have two concerns:

The first is that you don't call Close() on the ClientConn in the event of an error. Better to defer Close instead:

func YourFunction() (err error) {
  conn, err := grpc.Dial(...)
  if err != nil {
    return err
  }
  defer func() {
    closeErr := conn.Close()
    if err == nil {
      // Otherwise, we will return the primary error and ignore the error from Close.
      err = closeErr
    }
  }()
...

The second is that you have used context.Background() for your RPC context. This can be problematic. It would be better to either use a context with a deadline or make a child context with a cancel. I.e.

ctx, cancel := context.WithDeadline(context.Background(), 5*time.Second)
// or ctx, cancel := context.WithCancel(context.Background())
defer cancel()

Failure to cancel the context, or Close() the ClientConn (which you do here), or Recv from the stream until receiving a non-nil error (which you do not do here), will leak a goroutine.

One last note is that ClientConns are intended to be long-living. So if you have other RPCs you want to make to the server, or if you want to do this multiple times, it's better to create it once and keep it for as long as you need it, rather than per-RPC.

[minaevmike]

I add conn.Close to defer and there is still an error.
As i can see the problem is:
https://github.com/grpc/grpc-go/blob/master/transport/controlbuf.go#L295 , this done chan is ctx.Done() for this connection. I know that ClientCons are long-living but in this case this is just simple console client for manual testing. So i close connection on client side, server try to read frame and got an io.EOF https://github.com/grpc/grpc-go/blob/master/transport/http2_server.go#L448 and method Close called. In Close method context cancled and this error appears.

[JelteF]

As another datapoint. This has flooded our logs after updating to the latest gRPC. The reason for this is that we have a cronjob that connects to the process. We have now disabled all logging for gRPC because of this.

[MakMukhi]

Created a fix.