Skip to content
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

Jump to bottom

Added logs for reasons causing connection and transport close #5840

Merged
merged 8 commits into from
Dec 9, 2022
Merged

Added logs for reasons causing connection and transport close #5840

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
cfba279
Added logs throughout the transport layer for connection and transpor…
zasweq Dec 3, 2022
2b055c6
Responded to Doug's comments
zasweq Dec 6, 2022
c8bde09
Added error to ServerTransport.Stop
zasweq Dec 6, 2022
06978d0
Responded to Easwar's comments
zasweq Dec 7, 2022
4633d06
Switched all errors returned from loopyWriter.run() to info logs, and…
zasweq Dec 7, 2022
30d51f7
Responded to Doug and Easwar's comments
zasweq Dec 8, 2022
dd3ccea
Responded to Doug's comments
zasweq Dec 8, 2022
c2aa433
Doug's final comments
zasweq Dec 9, 2022
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
9 changes: 9 additions & 0 deletions internal/transport/controlbuf.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -416,6 +416,9 @@ func (c *controlBuffer) get(block bool) (interface{}, error) {
select {
case <-c.ch:
case <-c.done:
if logger.V(logLevel) {
logger.Infof("transport: trigger loopy to exit (with a subsequent conn closure) because transports context expired.")
Copy link
Member

Choose a reason for hiding this comment

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

Is ErrConnClosing significant here? If not, can we instead return a meaningful error and capture all the exit reasons via a single log after loopy returns (which IIUC is already there)?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Doesn't look like ErrConnClosing is used as a conditional/invariant anywhere in the system. Shoving this message/information into Error and logging at loopyWriter level sgtm.

Copy link
Contributor

Choose a reason for hiding this comment

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

s/transports/transport's/

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done @easwars.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Actually, I'm blind, and ErrConnClosing is used as a conditional in many many places at the control buf layer. Leaving this as is for now, unless you have a better suggestion.

}
return nil, ErrConnClosing
}
}
Expand Down Expand Up @@ -772,6 +775,9 @@ func (l *loopyWriter) cleanupStreamHandler(c *cleanupStream) error {
}
}
if l.side == clientSide && l.draining && len(l.estdStreams) == 0 {
if logger.V(logLevel) {
logger.Infof("transport: trigger loopy to exit (with a subsequent conn closure) because no active streams left to finish processing while in draining mode.")
}
return ErrConnClosing
}
return nil
Expand Down Expand Up @@ -807,6 +813,9 @@ func (l *loopyWriter) incomingGoAwayHandler(*incomingGoAway) error {
if l.side == clientSide {
l.draining = true
if len(l.estdStreams) == 0 {
if logger.V(logLevel) {
logger.Infof("transport: trigger loopy to exit (with a subsequent conn closure) because no active streams to wait to finish processing when GOAWAY frame received.")
}
return ErrConnClosing
}
}
Expand Down
47 changes: 41 additions & 6 deletions internal/transport/http2_client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -223,6 +223,9 @@ func newHTTP2Client(connectCtx, ctx context.Context, addr resolver.Address, opts
// Any further errors will close the underlying connection
defer func(conn net.Conn) {
if err != nil {
if logger.V(logLevel) {
logger.Errorf("transport: closing connection due to error %v.", err)
dfawley marked this conversation as resolved.
Show resolved Hide resolved
dfawley marked this conversation as resolved.
Show resolved Hide resolved
}
conn.Close()
}
}(conn)
Expand All @@ -244,6 +247,9 @@ func newHTTP2Client(connectCtx, ctx context.Context, addr resolver.Address, opts
<-newClientCtx.Done() // Block until connectCtx expires or the defer above executes.
if connectCtx.Err() != nil {
// connectCtx expired before exiting the function. Hard close the connection.
if logger.V(logLevel) {
logger.Infof("transport: closing connection due to connect context expiring.")
easwars marked this conversation as resolved.
Show resolved Hide resolved
dfawley marked this conversation as resolved.
Show resolved Hide resolved
}
conn.Close()
}
}(conn)
Expand Down Expand Up @@ -396,6 +402,9 @@ func newHTTP2Client(connectCtx, ctx context.Context, addr resolver.Address, opts
err = <-readerErrCh
}
if err != nil {
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to error reading server preface: %v.", err)
}
t.Close(err)
}
}()
Expand Down Expand Up @@ -447,7 +456,7 @@ func newHTTP2Client(connectCtx, ctx context.Context, addr resolver.Address, opts
err := t.loopy.run()
if err != nil {
if logger.V(logLevel) {
logger.Errorf("transport: loopyWriter.run returning. Err: %v", err)
logger.Errorf("transport: loopyWriter.run returned. Err: %v. Closing connection.", err)
Copy link
Contributor

Choose a reason for hiding this comment

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

Not always required, but mostly makes sense to add the existing error string to the end of the new one. Also, could we skip loopyWriter.run and replace it with something more readable?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

loopyWriter returned? loopyWriter exited? loopyWriter finished? I went with third option. Line switched to: logger.Errorf("transport: loopyWriter exited. Closing connection. Err: %v", err).

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I kept Err: %v in this and one below even though I switched ones above to consise errors ^^^ without an Err: and just : because I felt like these were important due to the "collection" point of these two.

}
}
// Do not close the transport. Let reader goroutine handle it since
Expand Down Expand Up @@ -965,6 +974,9 @@ func (t *http2Client) Close(err error) {
t.mu.Unlock()
t.controlBuf.finish()
t.cancel()
if logger.V(logLevel) {
logger.Infof("transport: calling Close on the conn within transport.Close.")
}
dfawley marked this conversation as resolved.
Show resolved Hide resolved
t.conn.Close()
channelz.RemoveEntry(t.channelzID)
// Append info about previous goaways if there were any, since this may be important
Expand Down Expand Up @@ -1007,6 +1019,9 @@ func (t *http2Client) GracefulClose() {
active := len(t.activeStreams)
t.mu.Unlock()
if active == 0 {
if logger.V(logLevel) {
logger.Infof("transport: closing transport because no active streams left to process in GracefulClose call.")
}
dfawley marked this conversation as resolved.
Show resolved Hide resolved
t.Close(ErrConnClosing)
return
}
Expand Down Expand Up @@ -1255,7 +1270,11 @@ func (t *http2Client) handleGoAway(f *http2.GoAwayFrame) {
id := f.LastStreamID
if id > 0 && id%2 == 0 {
t.mu.Unlock()
t.Close(connectionErrorf(true, nil, "received goaway with non-zero even-numbered numbered stream id: %v", id))
err := connectionErrorf(true, nil, "received goaway with non-zero even-numbered numbered stream id: %v", id)
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to error in goaway handling: %v.", err)
}
dfawley marked this conversation as resolved.
Show resolved Hide resolved
t.Close(err)
return
}
// A client can receive multiple GoAways from the server (see
Expand All @@ -1273,7 +1292,11 @@ func (t *http2Client) handleGoAway(f *http2.GoAwayFrame) {
// If there are multiple GoAways the first one should always have an ID greater than the following ones.
if id > t.prevGoAwayID {
t.mu.Unlock()
t.Close(connectionErrorf(true, nil, "received goaway with stream id: %v, which exceeds stream id of previous goaway: %v", id, t.prevGoAwayID))
err := connectionErrorf(true, nil, "received goaway with stream id: %v, which exceeds stream id of previous goaway: %v", id, t.prevGoAwayID)
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to error in goaway handling: %v.", err)
}
t.Close(err)
return
}
default:
Expand All @@ -1296,7 +1319,11 @@ func (t *http2Client) handleGoAway(f *http2.GoAwayFrame) {
t.prevGoAwayID = id
if len(t.activeStreams) == 0 {
t.mu.Unlock()
t.Close(connectionErrorf(true, nil, "received goaway and there are no active streams"))
err := connectionErrorf(true, nil, "received goaway and there are no active streams")
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to error in goaway handling: %v.", err)
}
t.Close(err)
return
}

Expand Down Expand Up @@ -1602,7 +1629,11 @@ func (t *http2Client) reader(errCh chan<- error) {
continue
} else {
// Transport error.
t.Close(connectionErrorf(true, err, "error reading from server: %v", err))
err := connectionErrorf(true, err, "error reading from server: %v", err)
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to connection level error %v.", err)
}
t.Close(err)
return
}
}
Expand Down Expand Up @@ -1661,7 +1692,11 @@ func (t *http2Client) keepalive() {
continue
}
if outstandingPing && timeoutLeft <= 0 {
t.Close(connectionErrorf(true, nil, "keepalive ping failed to receive ACK within timeout"))
err := connectionErrorf(true, nil, "keepalive ping failed to receive ACK within timeout")
if logger.V(logLevel) {
logger.Errorf("transport: closing transport due to error in keep alive handling: %v.", err)
easwars marked this conversation as resolved.
Show resolved Hide resolved
}
t.Close(err)
return
}
t.mu.Lock()
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 @@ -333,7 +333,7 @@ func NewServerTransport(conn net.Conn, config *ServerConfig) (_ ServerTransport,
t.loopy.ssGoAwayHandler = t.outgoingGoAwayHandler
if err := t.loopy.run(); err != nil {
dfawley marked this conversation as resolved.
Show resolved Hide resolved
if logger.V(logLevel) {
logger.Errorf("transport: loopyWriter.run returning. Err: %v", err)
logger.Errorf("transport: loopyWriter.run returned. Err: %v. Closing Connection.", err)
}
}
t.conn.Close()
Expand Down Expand Up @@ -630,18 +630,24 @@ func (t *http2Server) HandleStreams(handle func(*Stream), traceCtx func(context.
continue
}
if err == io.EOF || err == io.ErrUnexpectedEOF {
if logger.V(logLevel) {
logger.Infof("transport: closing the server transport due to connection level EOF.")
}
dfawley marked this conversation as resolved.
Show resolved Hide resolved
t.Close()
return
}
if logger.V(logLevel) {
logger.Warningf("transport: http2Server.HandleStreams failed to read frame: %v", err)
logger.Warningf("transport: http2Server.HandleStreams failed to read frame: %v, closing transport.", err)
}
t.Close()
return
}
switch frame := frame.(type) {
case *http2.MetaHeadersFrame:
if t.operateHeaders(frame, handle, traceCtx) {
if logger.V(logLevel) {
logger.Errorf("transport: closing the transport due to fatal error processing headers frame.")
}
t.Close()
break
}
Expand Down Expand Up @@ -1170,7 +1176,7 @@ func (t *http2Server) keepalive() {
}
if outstandingPing && kpTimeoutLeft <= 0 {
if logger.V(logLevel) {
logger.Infof("transport: closing server transport due to idleness.")
logger.Infof("transport: closing server transport due to keep alive ping not being acked within timeout %v.", t.kp.Time.String())
easwars marked this conversation as resolved.
Show resolved Hide resolved
}
t.Close()
return
Expand Down Expand Up @@ -1211,6 +1217,9 @@ func (t *http2Server) Close() {
t.mu.Unlock()
t.controlBuf.finish()
close(t.done)
if logger.V(logLevel) {
logger.Infof("transport: calling Close on the conn within transport.Close.")
}
if err := t.conn.Close(); err != nil && logger.V(logLevel) {
logger.Infof("transport: error closing conn during Close: %v", err)
}
Expand Down Expand Up @@ -1320,6 +1329,9 @@ func (t *http2Server) outgoingGoAwayHandler(g *goAway) (bool, error) {
t.state = draining
sid := t.maxStreamID
if len(t.activeStreams) == 0 {
if logger.V(logLevel) {
logger.Infof("transport: second goaway written and no active streams left to process, closing the connection.")
dfawley marked this conversation as resolved.
Show resolved Hide resolved
}
g.closeConn = true
}
t.mu.Unlock()
Expand Down