net/http: shouldn't log errors for normal Keep-Alive connection closures

[FiloSottile]

A Keep-Alive connection is going to end in one of two ways: the client goes away (maybe sending GOAWAY), or we pass the IdleTimeout. Neither are errors, but both are logged as such.

In HTTP/2, they look like this:

http2: error reading preface from client: timeout waiting for client preface
http2: error reading preface from client: connection reset by peer
http2: received GOAWAY, starting graceful shutdown

Not sure how they look like in HTTP 1. Probably just EOF.

These should just be ignored for idle connections.

P.S. I also see a sprinkle of these, not sure what to think about them yet, but they are rare:

http2: server: error reading preface from client: write tcp: write: broken pipe

[bradfitz]

I agree in general, but this one isn't an "idle" connection:

http2: error reading preface from client: timeout waiting for client preface

That's a new connection starting up. Don't we also log about TLS handshake errors? I think those are in the same class: connection setup errors.

[FiloSottile]

Are you sure that's not how an elapsed IdleTimeout looks like?

I think the connection setup ones are more like

h2_bundle.go:3331: timeout waiting for SETTINGS frames

[bradfitz]

http2: received GOAWAY, starting graceful shutdown

That was never the text? In https://go-review.googlesource.com/32887 @tombergan added:

@@ -1441,6 +1443,20 @@ func (sc *serverConn) processData(f *DataFrame) error {
        return nil
 }
 
+func (sc *serverConn) processGoAway(f *GoAwayFrame) error {
+       sc.serveG.check()
+       if f.ErrCode != ErrCodeNo {
+               sc.logf("http2: received GOAWAY %+v, starting graceful shutdown", f)
+       } else {
+               sc.vlogf("http2: received GOAWAY %+v, starting graceful shutdown", f)
+       }
+       sc.goAwayIn(ErrCodeNo, 0)
+       // http://tools.ietf.org/html/rfc7540#section-6.8
+       // We should not create any new streams, which means we should disable push.
+       sc.pushEnabled = false
+       return nil
+}
+

And we only log loudly on non-ErrCodeNo.

The idle timeout path looks fine too.

Can you update this bug with the version you're using and what log spam remains? I can't see obvious spam remaining.

[jameshartig]

I'll chime in as I can provide some clarity. We're using Golang 1.8 and we have IdleTimeout set as well to 3 minutes.

http2: error reading preface from client: timeout waiting for client preface

We get those ~5k/hr. Seem to be related to idle timeouts but we're still investigating.

http2: received GOAWAY [FrameHeader GOAWAY len=20], starting graceful shutdown
http2: received GOAWAY [FrameHeader GOAWAY len=8], starting graceful shutdown

Is what we get ~200/hr. Not sure if that provides any clarity with the extra frame information.

timeout waiting for SETTINGS frames

Happens ~500/hr. Haven't started debugging these.

We haven't yet finished debugging those and determining their root cause, but if they're like the TLS handshake errors (which I posted about to golang-nuts), they're just client-side issues that we can't do anything about.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[bradfitz]

http2: error reading preface from client: timeout waiting for client preface

That happens if somebody negotiates "h2" mode but then never says anything. That seems odd and rare enough to warn about. But if it really happens that often, we can demote it I guess.

http2: received GOAWAY [FrameHeader GOAWAY len=20], starting graceful shutdown
http2: received GOAWAY [FrameHeader GOAWAY len=8], starting graceful shutdown

Yeah, we shouldn't log those by default.

timeout waiting for SETTINGS frames

Probably a buggy client?

/cc @tombergan

[tombergan]

I will downgrade all of these to GODEBUG=http2debug=1

http2: error reading preface from client: timeout waiting for client preface

That happens if somebody negotiates "h2" mode but then never says anything. That seems odd and rare enough to warn about. But if it really happens that often, we can demote it I guess.

I think this might be a browser preconnect or happy-eyeballs thing. I've seen this a lot when testing with Chrome as the client.

[rsc]

Should we reduce logging verbosity for Go 1.10 for this, or just punt to Go 1.11?

[bradfitz]

Let's do it for Go 1.10. Simple and low risk.

[gopherbot]

Change https://golang.org/cl/79498 mentions this issue: http2: don't log about timeouts reading client preface on new connections

[gopherbot]

Change https://golang.org/cl/80078 mentions this issue: net/http: update bundled http2