Skip to content

internal/transport: skip log on EOF when reading client preface #4458

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
easwars merged 3 commits into from
Jun 2, 2021
Merged

internal/transport: skip log on EOF when reading client preface #4458

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
706faba
internal/transport: skip log on EOF when reading client preface
easwars May 18, 2021
6ce99c0
review comments
easwars May 19, 2021
a2b7c81
skip logs on EOF for secure connections as well
easwars Jun 2, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion call_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -160,7 +160,7 @@ func (s *server) start(t *testing.T, port int, maxStreams uint32) {
config := &transport.ServerConfig{
MaxStreams: maxStreams,
}
st, err := transport.NewServerTransport("http2", conn, config)
st, err := transport.NewServerTransport(conn, config)
if err != nil {
continue
}
Expand Down
18 changes: 15 additions & 3 deletions internal/transport/http2_server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,9 +125,14 @@ type http2Server struct {
connectionID uint64
}

// newHTTP2Server constructs a ServerTransport based on HTTP2. ConnectionError is
// returned if something goes wrong.
func newHTTP2Server(conn net.Conn, config *ServerConfig) (_ ServerTransport, err error) {
// NewServerTransport creates a http2 transport with conn and configuration
// options from config.
//
// It returns a non-nil transport and a nil error on success. On failure, it
// returns a non-nil transport and a nil-error. For a special case where the
// underlying conn gets closed before the client preface could be read, it
// returns a nil transport and a nil error.
func NewServerTransport(conn net.Conn, config *ServerConfig) (_ ServerTransport, err error) {
writeBufSize := config.WriteBufferSize
readBufSize := config.ReadBufferSize
maxHeaderListSize := defaultServerMaxHeaderListSize
Expand Down Expand Up @@ -266,6 +271,13 @@ func newHTTP2Server(conn net.Conn, config *ServerConfig) (_ ServerTransport, err
// Check the validity of client preface.
preface := make([]byte, len(clientPreface))
if _, err := io.ReadFull(t.conn, preface); err != nil {
// In deployments where a gRPC server runs behind a cloud load balancer
// which performs regular TCP level health checks, the connection is
// closed immediately by the latter. Skipping the error here will help
// reduce log clutter.
if err == io.EOF {
Copy link
Member

@dfawley dfawley May 18, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about io.ErrUnexpectedEOF?

Copy link
Contributor Author

@easwars easwars May 19, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I thought about this we check for that in line 283. But I decided not to have it here because we did not have it prior to the refactor in 1739d3b

Copy link
Member

@dfawley dfawley May 21, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this a regression? Maybe the logs were happening before that refactor, too? I would think either error could be safely skipped.

Copy link
Contributor Author

@easwars easwars Jun 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the documentation from ReadFull:

// ReadFull reads exactly len(buf) bytes from r into buf.
// It returns the number of bytes copied and an error if fewer bytes were read.
// The error is EOF only if no bytes were read.
// If an EOF happens after reading some but not all the bytes,
// ReadFull returns ErrUnexpectedEOF.

Given that we are trying to avoid logging for the case where the connection is closed as soon as it is made, I feel it makes more sense to only consider io.EOF. In the case of io.ErrUnexpectedEOF, we would still have some bytes read, which seems like a totally different case and worth logging.

What do you think?

Copy link
Member

@dfawley dfawley Jun 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That seems reasonable.

return nil, nil
}
return nil, connectionErrorf(false, err, "transport: http2Server.HandleStreams failed to receive the preface from client: %v", err)
Comment on lines +274 to 281
Copy link
Member

@dfawley dfawley May 18, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems to only matter for plaintext connections, or else the peer is finishing the handshake.

Is this possibly an incomplete fix? Where do we handle handshaker errors? Do they log?

Copy link
Contributor Author

@easwars easwars May 19, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We initiate the handshake from grpc.Server.handleRawConn and fail the connection right there if the handshake fails. And yes, we do log it.

My understanding is that cloud load balancers which perform TCP handshakes do not use TLS. But yes, one could still create a log storm by trying to present an invalid certificate. But server deployments anyway need to handle situations like this (with some kind of firewall) since log storm is not the only problem in such sitations. Wdyt?

Copy link
Member

@dfawley dfawley May 21, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My understanding is that cloud load balancers which perform TCP handshakes do not use TLS

But these logs are from the server, so it doesn't matter what the client is attempting to use. If it connects without TLS then the server's handshaker will fail it before we get here.

Copy link
Contributor Author

@easwars easwars Jun 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What we could do is that we could handle io.EOF as a special case here just like how err != credentials.ErrConnDispatched is being handled, and not add a log here.
https://github.com/grpc/grpc-go/blob/master/server.go#L843-L855

Copy link
Member

@dfawley dfawley Jun 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, something like that might be a good idea, too.

Copy link
Contributor Author

@easwars easwars Jun 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done. Made the change to server.go.

}
if !bytes.Equal(preface, clientPreface) {
Expand Down
6 changes: 0 additions & 6 deletions internal/transport/transport.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -532,12 +532,6 @@ type ServerConfig struct {
HeaderTableSize *uint32
}

// NewServerTransport creates a ServerTransport with conn or non-nil error
// if it fails.
func NewServerTransport(protocol string, conn net.Conn, config *ServerConfig) (ServerTransport, error) {
return newHTTP2Server(conn, config)
}

// ConnectOptions covers all relevant options for communicating with the server.
type ConnectOptions struct {
// UserAgent is the application user agent.
Expand Down
2 changes: 1 addition & 1 deletion internal/transport/transport_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -323,7 +323,7 @@ func (s *server) start(t *testing.T, port int, serverConfig *ServerConfig, ht hT
if err != nil {
return
}
transport, err := NewServerTransport("http2", conn, serverConfig)
transport, err := NewServerTransport(conn, serverConfig)
if err != nil {
return
}
Expand Down
16 changes: 11 additions & 5 deletions server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -844,10 +844,16 @@ func (s *Server) handleRawConn(lisAddr string, rawConn net.Conn) {
// ErrConnDispatched means that the connection was dispatched away from
// gRPC; those connections should be left open.
if err != credentials.ErrConnDispatched {
s.mu.Lock()
s.errorf("ServerHandshake(%q) failed: %v", rawConn.RemoteAddr(), err)
s.mu.Unlock()
channelz.Warningf(logger, s.channelzID, "grpc: Server.Serve failed to complete security handshake from %q: %v", rawConn.RemoteAddr(), err)
// In deployments where a gRPC server runs behind a cloud load
// balancer which performs regular TCP level health checks, the
// connection is closed immediately by the latter. Skipping the
// error here will help reduce log clutter.
if err != io.EOF {
s.mu.Lock()
s.errorf("ServerHandshake(%q) failed: %v", rawConn.RemoteAddr(), err)
s.mu.Unlock()
channelz.Warningf(logger, s.channelzID, "grpc: Server.Serve failed to complete security handshake from %q: %v", rawConn.RemoteAddr(), err)
}
rawConn.Close()
}
rawConn.SetDeadline(time.Time{})
Expand Down Expand Up @@ -897,7 +903,7 @@ func (s *Server) newHTTP2Transport(c net.Conn, authInfo credentials.AuthInfo) tr
MaxHeaderListSize: s.opts.maxHeaderListSize,
HeaderTableSize: s.opts.headerTableSize,
}
st, err := transport.NewServerTransport("http2", c, config)
st, err := transport.NewServerTransport(c, config)
if err != nil {
s.mu.Lock()
s.errorf("NewServerTransport(%q) failed: %v", c.RemoteAddr(), err)
Expand Down