S3 Client: HTTP Connection Reuse Fails Once Per 100 Requests #2825

shanebarnes · 2019-09-11T14:10:34Z

The SDK appears to prevent Golang's HTTP connection pool from reusing a connection after 100 requests have been made successfully with a single HTTP connection.

Version of AWS SDK for Go?

I have observed this behavior on multiple versions of the SDK including:

v1.23.19, and
v.1.16.11.

Version of Go (`go version`)?

I have observed this behavior on multiple versions of Go including:

1.13, and
1.12.

What issue did you see?

When I upload files to a S3 bucket using the S3 client using either the PutObjectRequest() or UploadPartRequest() interface, it appears that the underlying HTTP/TCP connection is only reused at most for 100 requests before a new HTTP/TCP connection is created. This happens even when a single HTTP/TCP connection is busy enough to prevent an idle connection timeout from occurring and without any requests failing.

I have observed this behavior on Ubuntu 16.04 LTS and macOS 10.14.

Steps to reproduce

The sample program below uploads 101 "files" in a short amount of time. Each request prints out whether the HTTP/TCP connection was reused and the status of the completed request (success or failure).

package main

import (
	"bytes"
	"fmt"
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"net/http/httptrace"
	"strconv"
	"time"

	"github.com/aws/aws-sdk-go/aws"
	"github.com/aws/aws-sdk-go/aws/request"
	"github.com/aws/aws-sdk-go/aws/session"
	"github.com/aws/aws-sdk-go/service/s3"
)

func main() {
	fmt.Println("Starting connection pool test")
	bucket := "my-bucket"
	disableSsl := false
	keyPrefix := "test"
	keySize := 1024
	region := "us-east-1"

	transport := &http.Transport{
		Dial: (&net.Dialer{
			DualStack:     true,
			Timeout:       30 * time.Second,
			KeepAlive:     45 * time.Second,
		}).Dial,
		DisableCompression:  false,
		DisableKeepAlives:   false,
		MaxIdleConns:        100,
		MaxIdleConnsPerHost: 100,
		IdleConnTimeout:     10 * time.Minute,
		TLSHandshakeTimeout: 30 * time.Second}

	client := &http.Client{Timeout: 0, Transport: transport}

	trace := httptrace.ClientTrace{
		GotConn: func(info httptrace.GotConnInfo) {
			fmt.Println("LocalAddr:", info.Conn.LocalAddr(), ", RemoteAddr:", info.Conn.RemoteAddr(), ", Reused:", info.Reused)
		}}

	config := aws.NewConfig().
		//WithLogLevel(aws.LogDebug).
		WithHTTPClient(client).
		WithMaxRetries(0).
		WithRegion(region).
		WithDisableSSL(disableSsl)

	svc := s3.New(session.New(), config)

	// Ensure that response body is drained
	svc.Handlers.Complete.PushBack(func(req *request.Request) {
		defer req.HTTPResponse.Body.Close()
		io.Copy(ioutil.Discard, req.HTTPResponse.Body)
	})

	for i := 0; i < 101; i++ {
		key := keyPrefix + "_" + strconv.Itoa(i+1)
		buf := make([]byte, keySize, keySize)
		objInput := &s3.PutObjectInput{
			Bucket: aws.String(bucket),
			Key:    aws.String(key),
			Body:   bytes.NewReader(buf),
		}

		req, _/*resp*/ := svc.PutObjectRequest(objInput)
		req.HTTPRequest = req.HTTPRequest.WithContext(httptrace.WithClientTrace(req.HTTPRequest.Context(), &trace))
		if err := req.Send(); err == nil {
			fmt.Println(key, ": PutObjectRequest succeeded")
		} else {
			fmt.Println(key, ": PutObjectRequest failed")
		}

		time.Sleep(10 * time.Millisecond)
	}

	fmt.Println("Completed connection pool test")
}

When the preceding code sample is run, the following output occurs:

Starting connection pool test
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: false
test_1 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_2 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_3 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_4 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_5 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_6 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_7 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_8 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_9 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_10 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_11 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_12 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_13 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_14 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_15 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_16 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_17 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_18 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_19 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_20 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_21 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_22 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_23 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_24 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_25 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_26 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_27 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_28 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_29 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_30 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_31 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_32 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_33 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_34 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_35 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_36 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_37 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_38 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_39 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_40 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_41 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_42 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_43 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_44 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_45 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_46 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_47 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_48 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_49 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_50 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_51 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_52 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_53 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_54 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_55 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_56 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_57 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_58 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_59 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_60 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_61 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_62 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_63 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_64 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_65 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_66 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_67 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_68 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_69 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_70 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_71 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_72 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_73 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_74 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_75 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_76 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_77 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_78 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_79 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_80 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_81 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_82 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_83 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_84 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_85 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_86 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_87 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_88 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_89 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_90 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_91 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_92 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_93 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_94 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_95 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_96 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_97 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_98 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_99 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54017 , RemoteAddr: 52.216.130.67:443 , Reused: true
test_100 : PutObjectRequest succeeded
LocalAddr: 10.0.77.68:54018 , RemoteAddr: 52.216.130.67:443 , Reused: false
test_101 : PutObjectRequest succeeded
Completed connection pool test

The text was updated successfully, but these errors were encountered:

diehlaws · 2019-09-20T17:23:52Z

Hi @shanebarnes, thanks for reaching out to us about this. After doing some testing I've found that this looks to be a behavior of S3 rather than the AWS SDK for Go - after S3 receives 100 requests on a given connection it will close this connection, forcing the client to create a new connection for the following 100 requests.

shanebarnes · 2019-09-21T00:20:14Z

Thanks @diehlaws for the explanation. I was able to confirm as well using Wireshark that the Connection: close header was being returned by the server in response to the 100th request. Strangely enough, I started printing out all headers in the responses in my sample code and was not able to see the Connection: close header. Thanks again.

jasdel · 2019-09-21T02:31:05Z

I think the lack of Connection closed header is due to the Go HTTP client or transport removing that header.

diehlaws · 2019-10-03T22:06:10Z

@shanebarnes No problem! I'll go ahead and close out this issue since it doesn't look like there's anything left to do here, if you have further questions for us about this please feel free to comment on the issue and/or re-open it so we can continue working with you on this.

diehlaws self-assigned this Sep 11, 2019

diehlaws added the investigating This issue is being investigated and/or work is in progress to resolve the issue. label Sep 11, 2019

diehlaws added service-api This issue is due to a problem in a service API, not the SDK implementation. and removed investigating This issue is being investigated and/or work is in progress to resolve the issue. labels Sep 20, 2019

diehlaws added the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. label Sep 20, 2019

diehlaws closed this as completed Oct 3, 2019

diehlaws removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. label Oct 3, 2019

zmagg mentioned this issue May 11, 2020

Let's try reverting. tinyspeck/vitess#156

Merged

diehlaws removed their assignment Aug 26, 2020

t089 mentioned this issue Jul 5, 2021

AHC might have a problem with remotes that close the connection swift-server/async-http-client#387

Closed

jmcshane mentioned this issue Mar 14, 2022

Connection reuse causing intermittent 503 errors from cilium-envoy cilium/cilium#19136

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

S3 Client: HTTP Connection Reuse Fails Once Per 100 Requests #2825

S3 Client: HTTP Connection Reuse Fails Once Per 100 Requests #2825

shanebarnes commented Sep 11, 2019 •

edited

Loading

diehlaws commented Sep 20, 2019

shanebarnes commented Sep 21, 2019

jasdel commented Sep 21, 2019

diehlaws commented Oct 3, 2019

S3 Client: HTTP Connection Reuse Fails Once Per 100 Requests #2825

S3 Client: HTTP Connection Reuse Fails Once Per 100 Requests #2825

Comments

shanebarnes commented Sep 11, 2019 • edited Loading

Version of AWS SDK for Go?

Version of Go (go version)?

What issue did you see?

Steps to reproduce

diehlaws commented Sep 20, 2019

shanebarnes commented Sep 21, 2019

jasdel commented Sep 21, 2019

diehlaws commented Oct 3, 2019

shanebarnes commented Sep 11, 2019 •

edited

Loading

Version of Go (`go version`)?