Shopify/brigade — pull request #18 by aybabtme (2014-08-10 02:31:24+00:00)
Title: Set timeouts on HTTP Header/TLS handshake

## Problem

After syncing 58 million keys, brigade sometimes hang on a few remaining connections.

```
"brigade.sync.decodedKeys": 58762892
"brigade.sync.fileLines": 58762892
"brigade.sync.inflight": 2 // <-- here
"brigade.sync.syncAbandoned": 44640
"brigade.sync.syncAttempted": 59338600
"brigade.sync.syncOk": 58718250
```

This can be confirmed with `netstat`:

```
$ netstat -n -p -e -e -o | grep brigade
(Not all processes could be identified, non-owned process info
will not be shown, you would have to be root to see it all.)
tcp 0 0 10.92.71.56:35456 176.32.100.241:443 ESTABLISHED 8025 256765521 24377/brigade off (0.00/0/0)
tcp 0 0 10.92.71.56:50819 54.231.14.72:443 ESTABLISHED 8025 206664449 24377/brigade off (0.00/0/0)
```

Looking at the `/debug/pprof/` endpoint and getting a stacktrace from the running brigade process we can see the s3 package is doing a call to Amazon:

```
goroutine 13286300 [select, 2886 minutes]:
net/http.(*persistConn).roundTrip(0xc21c83c000, 0xc208259c60, 0x0, 0x0, 0x0)
/usr/local/go/src/pkg/net/http/transport.go:1015 +0x6db
// more stuff
github.com/aybabtme/goamz/s3.(*S3).run(0xc2081042c0, 0xc209329180, 0x6bb820, 0xc209cb2960, 0x6d6b20, 0x0, 0x0)
// more stuff ///
```

This location in `http.RoundTrip` is the `select` case here:

```go
WaitResponse:
for {
select {
case err := <-writeErrCh: // waits for the `write` job to finish
if err != nil {
re = responseAndError{nil, err}
pc.close()
break WaitResponse
}
if d := pc.t.ResponseHeaderTimeout; d > 0 {
respHeaderTimer = time.After(d)
}
case <-pconnDeadCh:
// ...
case <-failTicker:
// ...
case <-respHeaderTimer: // times out if respHeaderTimer was set by write job case
pc.close()
re = responseAndError{err: errTimeout}
break WaitResponse
case re = <-resc: // waits for read job
break WaitResponse
}
}
```

So any of those cases could be responsible for hanging the HTTP call.

Further in the stack trace, with 2886 minutes waiting, we see that the goroutine in `writeLoop` did send bytes to the server, and is waiting for another write job:

```
goroutine 26221304 [select, 2886 minutes]:
net/http.(*persistConn).writeLoop(0xc21c83c000)
/usr/local/go/src/pkg/net/http/transport.go:885 +0x38f
created by net/http.(*Transport).dialConn
/usr/local/go/src/pkg/net/http/transport.go:601 +0x957
```

Since a write succeeded, if the `ResponseHeaderTimeout` would be set on the `http.Transport`, a timer would exist to error when no bytes are received from Amazon.

```go
case err := <-writeErrCh: // waits for the `write` job to finish
if err != nil {
re = responseAndError{nil, err}
pc.close()
break WaitResponse
}
if d := pc.t.ResponseHeaderTimeout; d > 0 {
respHeaderTimer = time.After(d)
}
```

However this field is not set by default in `goamz`.

Another event that could unblock the request would be a `read` from the server, however
we see that a read on the connection has been hanging for 2886 minutes as well, waiting for data:

```
goroutine 26221303 [IO wait, 2886 minutes]:
net.runtime_pollWait(0x7f0106d4a748, 0x72, 0x0)
/usr/local/go/src/pkg/runtime/netpoll.goc:146 +0x66
net.(*pollDesc).Wait(0xc2088f1db0, 0x72, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(*pollDesc).WaitRead(0xc2088f1db0, 0x0, 0x0)
/usr/local/go/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(*netFD).Read(0xc2088f1d50, 0xc75cae7000, 0x1000, 0x1000, 0x0, 0x7f0106d36418, 0xb)
/usr/local/go/src/pkg/net/fd_unix.go:232 +0x34c
// more stuff //
net/http.(*persistConn).readLoop(0xc21c83c000)
/usr/local/go/src/pkg/net/http/transport.go:782 +0x95
created by net/http.(*Transport).dialConn
/usr/local/go/src/pkg/net/http/transport.go:600 +0x93f
```

## In short

Somehow, `goamz` establishes a connection, then makes an HTTP call to S3. This call sends its bytes properly but never receives a response. Because no timeouts are set for HTTP response headers, this hangs _'forever'_.

## Solution

Fix `goamz` to support timeouts on HTTP response header.

By default, goamz doesn't set timeouts on network calls. It also doesn't support putting timeouts on the `http.Transport` for headers and TLS handshake. I've fixed my fork to always set the timeouts, and enabled the timeouts on all s3 objects.

r: @camilo @fbogsany
cc: @Shopify/webscale