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.

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

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

Closed
FiloSottile opened this issue Jan 24, 2017 · 11 comments
Closed
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@FiloSottile
Copy link
Contributor

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 bradfitz added this to the Go1.9 milestone Jan 24, 2017
@bradfitz
Copy link
Contributor

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
Copy link
Contributor Author

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
Copy link
Contributor

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.

@bradfitz bradfitz modified the milestones: Go1.9Maybe, Go1.9 May 24, 2017
@bradfitz bradfitz added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels May 24, 2017
@jameshartig
Copy link
Contributor

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
Copy link

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.)

@quentinmit quentinmit reopened this Jun 25, 2017
@quentinmit quentinmit removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jun 25, 2017
@quentinmit quentinmit reopened this Jun 25, 2017
@bradfitz
Copy link
Contributor

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

@bradfitz bradfitz modified the milestones: Go1.10, Go1.9Maybe Jul 20, 2017
@bradfitz bradfitz assigned tombergan and unassigned FiloSottile Jul 20, 2017
@tombergan
Copy link
Contributor

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
Copy link
Contributor

rsc commented Nov 22, 2017

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

@bradfitz
Copy link
Contributor

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

@bradfitz bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Nov 22, 2017
@gopherbot gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 22, 2017
@bradfitz bradfitz self-assigned this Nov 22, 2017
@gopherbot
Copy link

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

gopherbot pushed a commit to golang/net that referenced this issue Nov 22, 2017
…ions

Updates golang/go#18776

Change-Id: I7568f779e2b86c72c54c8744c08cc02988dde55b
Reviewed-on: https://go-review.googlesource.com/79498
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Tom Bergan <tombergan@google.com>
@gopherbot
Copy link

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

c3mb0 pushed a commit to c3mb0/net that referenced this issue Apr 2, 2018
…ions

Updates golang/go#18776

Change-Id: I7568f779e2b86c72c54c8744c08cc02988dde55b
Reviewed-on: https://go-review.googlesource.com/79498
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Tom Bergan <tombergan@google.com>
jasonwbarnett pushed a commit to jasonwbarnett/fileserver that referenced this issue Jul 11, 2018
Update http2 to x/net git rev db473f6b23.

(And un-skip TestWriteHeader0_h2 added in CL 80077, now fixed.)

Includes:

   http2: remove afterReqBodyWriteError wrapper
   https://golang.org/cl/75252

   http2: fix transport data race on reused *http.Request objects
   https://golang.org/cl/75530

   http2: require either ECDSA or RSA ciphersuite
   https://golang.org/cl/30721

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

   http2: don't crash in Transport on server's DATA following bogus HEADERS
   https://golang.org/cl/80056

   http2: panic on invalid WriteHeader status code
   https://golang.org/cl/80076

   http2: fix race on ClientConn.maxFrameSize
   https://golang.org/cl/79238

   http2: don't autodetect Content-Type when the response has an empty body
   https://golang.org/cl/80135

Fixes golang/go#18776
Updates golang/go#20784
Fixes golang/go#21316
Fixes golang/go#22721
Fixes golang/go#22880

Change-Id: Ie86e24e0ee2582a5a82afe5de3c7c801528be069
Reviewed-on: https://go-review.googlesource.com/80078
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Tom Bergan <tombergan@google.com>
@golang golang locked and limited conversation to collaborators Nov 28, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

7 participants