net/http: http tries to reuse dead TLS connections

[edsrzf]

The symptom is that requests occasionally fail with io.EOF. I've observed this when
making requests against AWS's ELB (Elastic Load Balancer), but it might happen elsewhere.

When ELB's load suddenly increases, it can respond with HTTP 503 errors while it warms
up. When it does this over HTTPS, it also sends a TLS close_notify alert but does not
close the connection itself.

Go's http package receives ELB's 503 responses just fine. However, it does not read the
close_notify alert and so doesn't realize that the TLS connection is effectively closed.
It then tries to reuse the same connection for its next request.

The next request's writes all succeed, but ELB is completely ignoring everything. Then
http attempts to read the response, the tls.Conn sees the close_notify alert from the
previous response, and the read returns io.EOF.

I can provide steps to reproduce the problem, but unfortunately they're kind of involved.

1. Sign up for an account on http://www.iron.io/
2. Create a project and take note of its project ID.
3. Get an API token from https://hud.iron.io/tokens
4. Run the attached program until it panics

Attachments:

1. mq_eof.go (499 bytes)

[bradfitz]

Comment 1:

Adam, thoughts on this?
I didn't know TSL even had a "close_notify" packet type.
For background: the HTTP transport code opens two goroutines: one for reading and one
for writing.  It stops using a TCP connection for HTTP (or HTTPS) once the remote side
says "Connection: close" (or HTTP/1.0 without Connection keep-alive), or once the reader
goroutine peeks a byte and it's EOF.
There might be two issues here:
1) Amazon ELB is not sending a Connection: close on its 503 response?
2) Peeking a byte on a tls.Conn should return EOF or something once it gets a
close_notify packet?  Or, if it already returns a different error, the net/http
Transport code should learn what it is.  I see no vars declared in crypto/tls, though.

Owner changed to @bradfitz.

Status changed to Accepted.

[edsrzf]

Comment 2:

I can confirm that ELB doesn't send a Connection: close on its 503. The only header it
sends with that is Content-Length: 0.

[bradfitz]

Comment 3:

In that case, it's totally legit AFAIU for us to re-use that connection.  If the Go
client has an outbound request ready before it sees the close_notify packet (assume we
do/will handle it correctly), there's a potential race between us sending a request and
us hearing that the connection is dead.

[edsrzf]

Comment 4:

I understand that ELB's behaving badly here, but other clients I've tried handle it
gracefully.
I also understand the potential race, but catching a dead TLS connection sometimes seems
better than catching it never.

[bradfitz]

Comment 5:

Agreed. I just want to set expectations: even if we have a tls.Conn and/or
http.Transport bug here and they get fixed, there will still be a race if you have a
busy client.
But that's likely true with any other language too. If you find that is NOT the case,
I'd be curious what other libraries due to avoid this. Treating a 503 as a dead
connection always seems lame, for instance, if that's the answer.

[agl]

Comment 6:

TLS has a secure EOF called "close_notify". In theory, every half-connection is closed
with a close-notify and any transport EOF without a close_notify is a truncation error.
In practice, things are very messy.
However, I can well believe that we ignore close_notify. If treating it as EOF fixes
this problem then that sounds like a reasonable thing to do.

[edsrzf]

Comment 7:

I believe close_notify is already treated as EOF. It's just that we don't end up reading
it straight after reading the response.
The sequence goes:
1. Request 1 is sent as normal
2. Response 1 is received as normal (and it happens to be a 503)
3. Request 2 is sent
4. We try to read response 2, but then realize that close_notify was sent straight after
response 1. Request 2 was totally ignored by the server. EOF is returned.

[bradfitz]

Comment 8:

I don't agree with comment #7's analysis.
The Transport always has a goroutine reading, even if a request hasn't been sent.

[rsc]

Comment 9:

#7's analysis sounds plausible to me.  Surely there is a race: we could plausibly finish
reading the response and then decide to send another request before the close notify has
arrived.  
That suggests a more general experiment that could be carried out.  Write an HTTP/1.1
server that answers with a framed request (or a Content-Length), so that the client
would think the connection could be reused, but then hang up on the client, say, 2
seconds after writing the response.  If we are keeping connections open in general then
this would simulate the server timing us out at exactly the moment we decide to issue a
new request.  It seems like we should redial in this situation.  Do we?

[edsrzf]

Comment 10:

I think the problem I was having ended up being my fault. I was retrying requests that
resulted in 503, and when that happened I was forgetting to close the response body.
I just need to remember my mantra: "It's always your fault."

[edsrzf]

Comment 11:

It still seems strange that the problem only occurred when using HTTPS, though. I
haven't fully thought through why that might be.

[rsc]

Comment 12:

Labels changed: added priority-later, removed priority-triage.

[rsc]

Comment 13:

Labels changed: added go1.1maybe.

[bradfitz]

Comment 14:

Here's a repro (HTTPS + fake keep-alive response with forced disconnect).  With the 500
millisecond sleep uncommented, it's reliable.  Without, you get varying errors:
serve_test.go:699:      Get https://127.0.0.1:38706/: EOF
serve_test.go:699:      Get https://127.0.0.1:58785/: http: can't write HTTP request on
broken connection
// Trying to repro golang.org/issue/3514
func TestTLSServerClosesConnection(t *testing.T) {
        closec := make(chan bool)
        closedc := make(chan bool)
        ts := httptest.NewTLSServer(HandlerFunc(func(w ResponseWriter, r *Request) {
                if strings.Contains(r.URL.Path, "/kill") {
                        conn, _, _ := w.(Hijacker).Hijack()
                        conn.Close()
                        return
                }
                if strings.Contains(r.URL.Path, "/keep-alive-then-die") {
                        conn, _, _ := w.(Hijacker).Hijack()
                        conn.Write([]byte("HTTP/1.1 200 OK\r\nContent-Length: 3\r\n\r\nfoo"))
                        <-closec
                        conn.Close()
                        closedc <- true
                        return
                }
                fmt.Fprintf(w, "hello")
        }))
        defer ts.Close()
        noVerifyTransport := &Transport{
        TLSClientConfig: &tls.Config{
                        InsecureSkipVerify: true,
                },
        }
        client := &Client{Transport: noVerifyTransport}
        _, err := client.Get(ts.URL + "/kill")
        if err == nil {
                t.Error("expected error from /kill request")
        }
        res, err := client.Get(ts.URL + "/keep-alive-then-die")
        if err != nil {
                t.Fatal(err)
        }
        slurp, err := ioutil.ReadAll(res.Body)
        if err != nil {
                t.Fatal(err)
        }
        if string(slurp) != "foo" {
                t.Errorf("Got %q, want foo", slurp)
        }
        closec <- true
        <-closedc
        // time.Sleep(500 * time.Millisecond)
        res, err = client.Get(ts.URL + "/")
        if err != nil {
                t.Fatal(err)
        }
        slurp, err = ioutil.ReadAll(res.Body)
        if err != nil {
                t.Fatal(err)
        }
        if string(slurp) != "hello" {
                t.Errorf("Got %q, want hello", slurp)
        }
}
The latter bug ("http: can't write HTTP request on broken connection") occurs before
we've written anything on the wire, so we could in theory back up a bit and pick a new
conn.
But the EOF one seems more common, and that's the one where we can't really do anything.
 Short of maybe issue #4677.
Not quite sure what to do here, if anything.

Status changed to Thinking.

[dborowitz]

Comment 15:

I'm running into a problem that sounds very similar, and wanted to add a few
observations. My test program is pasted at the bottom.
-This problem gets worse with concurrency. Running 1000 concurrent GET requests to
https://www.google.com consistently fails 0.1-1% of the time:
 $ go run test_get.go -c -s -n 1000 -u www.google.com | grep failed
2/1000 failed
Up that to 10000 concurrent requests and the rate skyrockets to >80%(!):
$ go run test_get.go -c -s -n 10000 -u www.google.com | grep failed
8441/10000 failed
-This problem also gets worse when redirects are involved, even without concurrency.
(For these I used google.com, which 301s to www.google.com.)
$ go run test_get.go -c -s -n 1000 -u google.com | grep failed
311/1000 failed
$ go run test_get.go -s -n 1000 -u google.com | grep failed
7/1000 failed
-Just as a control, which is what makes me suspect it's this bug, all of the above
report 0 failures without -s.
$ cat test_get.go 
package main
import (
        "flag"
        "fmt"
        "net/http"
)
var (
        n = flag.Int("n", 100, "number of GETs to run")
        s = flag.Bool("s", false, "whether to use HTTPS")
        c = flag.Bool("c", false, "whether to run concurrently")
        u = flag.String("u", "google.com", "URL to fetch, without scheme")
)
func main() {
        flag.Parse()
        out := make(chan error, *n)
        var url string
        if *s {
                url = fmt.Sprintf("https://%v", *u)
        } else {
                url = fmt.Sprintf("http://%v", *u)
        }
        for i := 0; i < *n; i++ {
                f := func() {
                        res, err := http.Get(url)
                        if res != nil {
                                res.Body.Close()
                        }
                        if err != nil {
                                out <- err
                        } else {
                                out <- nil
                        }
                }
                if *c {
                        go f()
                } else {
                        f()
                }
        }
        failed := 0
        for i := 0; i < *n; i++ {
                err := <-out
                if err != nil {
                        fmt.Println(err)
                        failed++
                }
        }
        fmt.Printf("%d/%d failed\n", failed, *n)
}