net/http: Transport wastes TLS handshake progress #50984

rhysh · 2022-02-02T21:09:09Z

What version of Go are you using (`go version`)?

$ go1.16 version
go version go1.16.13 darwin/arm64

$ go1.17 version
go version go1.17.6 darwin/arm64

$ go1.18 version
go version devel go1.18-41f485b9a7 Mon Jan 31 13:43:52 2022 +0000 darwin/arm64
# aka go1.18beta2

Does this issue reproduce with the latest release?

Yes, this is present in the latest stable release, go1.17.6, and the latest tagged beta. It is not present in go1.16.13. It was introduced by the work for #32406.

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go1.17 env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/rhys/Library/Caches/go-build"
GOENV="/Users/rhys/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/rhys/go/pkg/mod"
GONOPROXY="*"
GONOSUMDB="*"
GOOS="darwin"
GOPATH="/Users/rhys/go"
GOPRIVATE="*"
GOPROXY="direct"
GOROOT="/Users/rhys/go/version/go1.17"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/rhys/go/version/go1.17/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.17.6"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lf/n4ry0qv5639_3z0nhyhy3z7c0000gs/T/go-build3534659518=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

An application I work with uses net/http to make outbound requests over HTTP/1.1+TLS. It uses Context values to control the lifecycle of those requests and to set timeouts. It cleans up the Context values (to avoid leaking timers, as recommended by go vet) when the outbound HTTPS call is complete.

Here's an overview of the most relevant code:

func callWithTimeout(ctx context.Context) {
    ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
    defer cancel()
    doRequest(ctx) // uses net/http package for HTTPS call several layers down
}

I've included a full reproducer at the bottom, also available at https://go.dev/play/p/_vg00gqqbpG although the Playground's network stack messes slightly with the results.

What did you expect to see?

I expected that code pattern (use Context to set a timeout, clean up immediately after the call) to be a best practice. I expected it to lead to efficient use of compute resources. I expected it to provide good performance (not much unnecessary latency).

What did you see instead?

After upgrading the application from from Go 1.16 to Go 1.17, the load balancer in front of the HTTPS service this application calls saw about a 4x increase in the volume of inbound TLS handshake requests, while reporting no change in the typical number of concurrent connections. A 4x increase in TLS handshake volume for this service is enough to throw off capacity planning.

The reproducer shows that canceling the Context value that was used for a request that is now complete causes harm to the connection pool. It shows that when a request finds an empty pool and so triggers creation of a new connection, the link between the request that triggered the new connection outlives the request's need for that specific connection.

When another request to the same backend completes and makes its connection available in the Transport's pool, the request that triggered a new dial may use the now-idle connection instead. That allows the request to complete even before the connection it triggered is ready.

All recent Go versions include that link when executing a TCP handshake, leading to some TCP connections being closed as soon as they become ready thereby wasting the work of the DNS lookup and TCP handshake. New in Go 1.17 is an additional link to the TLS handshake, allowing that more-expensive work to be discarded. From the reproducer:

	// New in Go 1.17 via https://golang.org/issue/32406, Go's HTTP client
	// connection pool now also discards useful progress on outbound TLS
	// handshakes.
	//
	// At t=0ms, the first request triggers a new connection
	// At t=0ms, the TCP handshake for the first connection is complete and the TLS handshake begins
	// At t=200ms, the TLS handshake completes and the first HTTP request begins
	// At t=250ms, the first HTTP request completes and the first connection enters the idle pool
	// At t=400ms, the second request removes the first connection from the idle pool
	// At t=420ms, the third request finds an empty pool and dials a second connection
	// At t=420ms, the second connection TLS handshake begins
	// At t=450ms, the second HTTP request completes and hands its connection to the pool
	// At t=450ms, the third request intercepts the first connection before it enters the pool
	// At t=500ms, the third HTTP request completes and returns to the application code
	// At t=500ms, the application code has the full HTTP response, so cancels its Context
	// At t=500ms, Go 1.17's call to tls.Conn.HandshakeContext aborts
	// At t=620ms, Go 1.16's call to tls.Conn.Handshake completes, and goes into the idle pool
	// At t=800ms, the fourth request removes the first connection from the idle pool
	// At t=800ms, the fifth request uses an idle connection (Go 1.16) or dials fresh (Go 1.17+)
	t.Run("minimal pool with slow TLS", varyCancel(
		2,                    // ideal pool size
		0,                    // delay in TCP
		200*time.Millisecond, // delay in TLS
		50*time.Millisecond,  // delay in HTTP
		[]time.Duration{
			0,                      // t=0 ms     create connection 1
			400 * time.Millisecond, // t=400 ms   use warm connection 1 until t=450
			20 * time.Millisecond,  // t=420 ms   trigger new connection 2 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=800 ms   observe pool size (use 1)
			0,                      // t=800 ms   observe pool size (use 2, or dial 3)
		}))

With Go 1.17+, the idle pool remains smaller than what the application needs in the steady state. More requests find an empty pool and need to wait for a connection to become available (generally winning in the race against a freshly-dialed connection). The reproducer shows an increase to the average request duration, though I haven't measured that in a production setting. (TLS handshakes are expensive, not slow.)

Reproducer results

$ go1.16 test -v
=== RUN   TestHTTPDialCancel
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP
    dial_test.go:148: NOTE: expect failure here for all recent Go versions
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel
    dial_test.go:132: average duration 102.287083ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 3 > 2
    dial_test.go:130: timeout=20m0s tcp=3 tls=1 http=5
    dial_test.go:132: average duration 113.971666ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 101.454508ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:132: average duration 101.3856ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 75.285054ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:132: average duration 76.206017ms
--- FAIL: TestHTTPDialCancel (7.69s)
    --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP (1.78s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel (0.87s)
        --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel (0.92s)
    --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TLS (1.73s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel (0.87s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel (0.86s)
    --- PASS: TestHTTPDialCancel/large_pool_with_slow_TLS (4.17s)
        --- PASS: TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel (2.07s)
        --- PASS: TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel (2.10s)
FAIL
exit status 1
FAIL	code.justin.tv/rhys/nursery/issue/golang/go/50xxx	7.844s

$ go1.17 test -v
=== RUN   TestHTTPDialCancel
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP
    dial_test.go:148: NOTE: expect failure here for all recent Go versions
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel
    dial_test.go:132: average duration 103.162191ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 3 > 2
    dial_test.go:130: timeout=20m0s tcp=3 tls=1 http=5
    dial_test.go:132: average duration 114.508925ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 102.52155ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 3 > 2
    dial_test.go:127: TLS handshake count; 3 > 2
    dial_test.go:130: timeout=20m0s tcp=3 tls=3 http=5
    dial_test.go:132: average duration 113.051833ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 77.059902ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 24 > 8
    dial_test.go:127: TLS handshake count; 24 > 8
    dial_test.go:130: timeout=20m0s tcp=24 tls=24 http=44
    dial_test.go:132: average duration 87.613746ms
--- FAIL: TestHTTPDialCancel (8.04s)
    --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP (1.81s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel (0.87s)
        --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel (0.93s)
    --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TLS (1.89s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel (0.87s)
        --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel (1.02s)
    --- FAIL: TestHTTPDialCancel/large_pool_with_slow_TLS (4.34s)
        --- PASS: TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel (2.09s)
        --- FAIL: TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel (2.25s)
FAIL
exit status 1
FAIL	code.justin.tv/rhys/nursery/issue/golang/go/50xxx	8.780s

$ go1.18 test -v
=== RUN   TestHTTPDialCancel
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP
    dial_test.go:148: NOTE: expect failure here for all recent Go versions
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel
    dial_test.go:132: average duration 105.759366ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 3 > 2
    dial_test.go:130: timeout=20m0s tcp=3 tls=1 http=5
    dial_test.go:132: average duration 113.322008ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 101.212549ms
=== RUN   TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 3 > 2
    dial_test.go:127: TLS handshake count; 3 > 2
    dial_test.go:130: timeout=20m0s tcp=3 tls=3 http=5
    dial_test.go:132: average duration 116.365683ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel
    dial_test.go:132: average duration 76.463704ms
=== RUN   TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel
    dial_test.go:124: TCP handshake count; 24 > 8
    dial_test.go:127: TLS handshake count; 24 > 8
    dial_test.go:130: timeout=20m0s tcp=24 tls=24 http=44
    dial_test.go:132: average duration 90.389791ms
--- FAIL: TestHTTPDialCancel (8.01s)
    --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP (1.79s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TCP/no_timeout/cancel (0.87s)
        --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TCP/with_timeout/cancel (0.92s)
    --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TLS (1.88s)
        --- PASS: TestHTTPDialCancel/minimal_pool_with_slow_TLS/no_timeout/cancel (0.87s)
        --- FAIL: TestHTTPDialCancel/minimal_pool_with_slow_TLS/with_timeout/cancel (1.01s)
    --- FAIL: TestHTTPDialCancel/large_pool_with_slow_TLS (4.33s)
        --- PASS: TestHTTPDialCancel/large_pool_with_slow_TLS/no_timeout/cancel (2.08s)
        --- FAIL: TestHTTPDialCancel/large_pool_with_slow_TLS/with_timeout/cancel (2.25s)
FAIL
exit status 1
FAIL	code.justin.tv/rhys/nursery/issue/golang/go/50xxx	8.825s

Reproducer code, dial_test.go

// Copyright 2022 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package main

import (
	"context"
	"crypto/tls"
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net"
	"net/http"
	"net/http/httptest"
	"sync"
	"sync/atomic"
	"testing"
	"time"
)

func TestHTTPDialCancel(t *testing.T) {
	withServer := func(tcpDelay, tlsDelay, httpDelay time.Duration, fn func(srv *httptest.Server)) (int, int, int) {
		var (
			tcpDialCount      int32
			tlsHandshakeCount int32
			httpHandleCount   int32
		)

		srv := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			atomic.AddInt32(&httpHandleCount, 1)
			time.Sleep(httpDelay)
		}))

		srv.EnableHTTP2 = false

		srv.Config.ErrorLog = log.New(ioutil.Discard, "", 0)

		// Pause for a moment during the handshake so we can see what happens when
		// we cancel the Context of a completed HTTP Request.
		srv.TLS = &tls.Config{}
		srv.TLS.GetConfigForClient = func(chi *tls.ClientHelloInfo) (*tls.Config, error) {
			atomic.AddInt32(&tlsHandshakeCount, 1)
			time.Sleep(tlsDelay)
			return nil, nil
		}

		srv.StartTLS()
		defer srv.Close()

		// Before making any requests, add a delay to the TCP Dialer so we can see
		// what happens when we cancel the Context of a completed HTTP Request.
		srv.Client().Transport.(*http.Transport).DialContext = func(ctx context.Context, network, addr string) (net.Conn, error) {
			atomic.AddInt32(&tcpDialCount, 1)
			time.Sleep(tcpDelay)
			return (&net.Dialer{}).DialContext(ctx, network, addr)
		}
		// Allow a large connection pool
		srv.Client().Transport.(*http.Transport).MaxIdleConnsPerHost = 100

		fn(srv)

		return int(atomic.LoadInt32(&tcpDialCount)), int(atomic.LoadInt32(&tlsHandshakeCount)), int(atomic.LoadInt32(&httpHandleCount))
	}

	doRequest := func(ctx context.Context, srv *httptest.Server, timeout time.Duration) error {
		if timeout > 0 {
			// BUG: canceling the context associated with an already-complete
			// HTTP request leads to an increase in TLS handshake count.
			sub, cancel := context.WithTimeout(ctx, timeout)
			defer cancel()
			ctx = sub
		}

		req, err := http.NewRequestWithContext(ctx, "GET", srv.URL, nil)
		if err != nil {
			return fmt.Errorf("NewRequestWithContext: %w", err)
		}

		resp, err := srv.Client().Do(req)
		if err != nil {
			return fmt.Errorf("Do Request: %w", err)
		}
		defer resp.Body.Close()

		_, err = io.Copy(ioutil.Discard, resp.Body)
		if err != nil {
			return fmt.Errorf("Discard Body: %w", err)
		}

		return nil
	}

	callWithDelays := func(t *testing.T, tcpDelay, tlsDelay, httpDelay time.Duration, delays []time.Duration, timeout time.Duration) (int, int, int, time.Duration) {
		var total time.Duration
		tcp, tls, http := withServer(tcpDelay, tlsDelay, httpDelay, func(srv *httptest.Server) {
			ctx := context.Background()
			var wg sync.WaitGroup
			for _, delay := range delays {
				time.Sleep(delay)
				wg.Add(1)
				go func() {
					defer wg.Done()
					start := time.Now()
					err := doRequest(ctx, srv, timeout)
					if err != nil {
						t.Errorf("HTTP request failed: %v", err)
					}
					atomic.AddInt64((*int64)(&total), int64(time.Now().Sub(start)))
				}()
			}
			wg.Wait()
		})
		return tcp, tls, http, total / time.Duration(len(delays))
	}

	varyCancel := func(poolSize int, tcpDelay, tlsDelay, httpDelay time.Duration, delays []time.Duration) func(t *testing.T) {
		return func(t *testing.T) {
			fn := func(timeout time.Duration) func(t *testing.T) {
				return func(t *testing.T) {
					tcp, tls, http, avg := callWithDelays(t, tcpDelay, tlsDelay, httpDelay, delays, timeout)
					if tcp > poolSize {
						t.Errorf("TCP handshake count; %d > %d", tcp, poolSize)
					}
					if tls > poolSize {
						t.Errorf("TLS handshake count; %d > %d", tls, poolSize)
					}
					if t.Failed() {
						t.Logf("timeout=%s tcp=%d tls=%d http=%d", timeout, tcp, tls, http)
					}
					t.Logf("average duration %s", avg)
				}
			}
			// No timeout, so no context.WithCancel / WithTimeout call
			t.Run("no timeout/cancel", fn(0))
			// Huge timeout, key change is the presence of "defer cancel()" once
			// the outbound request is complete
			t.Run("with timeout/cancel", fn(20*time.Minute))
		}
	}

	// Go's HTTP client connection pool has discarded useful progress on
	// outbound TCP handshakes for several releases.
	//
	// NOTE: this test doesn't work well on the Playground.
	t.Run("minimal pool with slow TCP", func(t *testing.T) {
		t.Logf("NOTE: expect failure here for all recent Go versions")
		varyCancel(
			2,                    // ideal pool size
			200*time.Millisecond, // delay in TCP
			0,                    // delay in TLS
			50*time.Millisecond,  // delay in HTTP
			[]time.Duration{
				0,                      // t=0 ms     create connection 1
				400 * time.Millisecond, // t=400 ms   use warm connection 1 until t=450
				20 * time.Millisecond,  // t=420 ms   trigger new connection 2 (BUG: work may be discarded!)
				380 * time.Millisecond, // t=800 ms   observe pool size (use 1)
				0,                      // t=800 ms   observe pool size (use 2, or dial 3)
			})(t)
	})

	// New in Go 1.17 via https://golang.org/issue/32406, Go's HTTP client
	// connection pool now also discards useful progress on outbound TLS
	// handshakes.
	//
	// At t=0ms, the first request triggers a new connection
	// At t=0ms, the TCP handshake for the first connection is complete and the TLS handshake begins
	// At t=200ms, the TLS handshake completes and the first HTTP request begins
	// At t=250ms, the first HTTP request completes and the first connection enters the idle pool
	// At t=400ms, the second request removes the first connection from the idle pool
	// At t=420ms, the third request finds an empty pool and dials a second connection
	// At t=420ms, the second connection TLS handshake begins
	// At t=450ms, the second HTTP request completes and hands its connection to the pool
	// At t=450ms, the third request intercepts the first connection before it enters the pool
	// At t=500ms, the third HTTP request completes and returns to the application code
	// At t=500ms, the application code has the full HTTP response, so cancels its Context
	// At t=500ms, Go 1.17's call to tls.Conn.HandshakeContext aborts
	// At t=620ms, Go 1.16's call to tls.Conn.Handshake completes, and goes into the idle pool
	// At t=800ms, the fourth request removes the first connection from the idle pool
	// At t=800ms, the fifth request uses an idle connection (Go 1.16) or dials fresh (Go 1.17+)
	t.Run("minimal pool with slow TLS", varyCancel(
		2,                    // ideal pool size
		0,                    // delay in TCP
		200*time.Millisecond, // delay in TLS
		50*time.Millisecond,  // delay in HTTP
		[]time.Duration{
			0,                      // t=0 ms     create connection 1
			400 * time.Millisecond, // t=400 ms   use warm connection 1 until t=450
			20 * time.Millisecond,  // t=420 ms   trigger new connection 2 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=800 ms   observe pool size (use 1)
			0,                      // t=800 ms   observe pool size (use 2, or dial 3)
		}))

	// The impact of discarding useful progress on TLS handshakes is unbounded:
	// A client running Go 1.17 or newer, which creates a context for each
	// request which it cancels when the request is complete, may steadily churn
	// through new TLS connections. It can do this even when its maximum
	// outbound concurrency is below the MaxIdleConnsPerHost limit.
	t.Run("large pool with slow TLS", varyCancel(
		8,                    // ideal pool size
		0,                    // delay in TCP
		200*time.Millisecond, // delay in TLS
		50*time.Millisecond,  // delay in HTTP
		[]time.Duration{
			0,                      // t=0 ms     create connection 1
			0,                      // t=0 ms     create connection 2
			0,                      // t=0 ms     create connection 3
			0,                      // t=0 ms     create connection 4
			400 * time.Millisecond, // t=400 ms   use warm connection 1 until t=450
			0,                      // t=400 ms   use warm connection 2 until t=450
			0,                      // t=400 ms   use warm connection 3 until t=450
			0,                      // t=400 ms   use warm connection 4 until t=450
			20 * time.Millisecond,  // t=420 ms   trigger new connection 5 (BUG: work may be discarded!)
			0,                      // t=420 ms   trigger new connection 6 (BUG: work may be discarded!)
			0,                      // t=420 ms   trigger new connection 7 (BUG: work may be discarded!)
			0,                      // t=420 ms   trigger new connection 8 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=800 ms   use warm connection 1 until t=850
			0,                      // t=800 ms   use warm connection 2 until t=850
			0,                      // t=800 ms   use warm connection 3 until t=850
			0,                      // t=800 ms   use warm connection 4 until t=850
			20 * time.Millisecond,  // t=820 ms   use warm connection 5, or trigger new connection 9 (BUG: work may be discarded!)
			0,                      // t=820 ms   use warm connection 6, or trigger new connection 10 (BUG: work may be discarded!)
			0,                      // t=820 ms   use warm connection 7, or trigger new connection 11 (BUG: work may be discarded!)
			0,                      // t=820 ms   use warm connection 8, or trigger new connection 12 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=1200 ms  use warm connection 1 until t=1250
			0,                      // t=1200 ms  use warm connection 2 until t=1250
			0,                      // t=1200 ms  use warm connection 3 until t=1250
			0,                      // t=1200 ms  use warm connection 4 until t=1250
			20 * time.Millisecond,  // t=1220 ms  use warm connection 5, or trigger new connection 13 (BUG: work may be discarded!)
			0,                      // t=1220 ms  use warm connection 6, or trigger new connection 14 (BUG: work may be discarded!)
			0,                      // t=1220 ms  use warm connection 7, or trigger new connection 15 (BUG: work may be discarded!)
			0,                      // t=1220 ms  use warm connection 8, or trigger new connection 16 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=1600 ms  use warm connection 1 until t=1650
			0,                      // t=1600 ms  use warm connection 2 until t=1650
			0,                      // t=1600 ms  use warm connection 3 until t=1650
			0,                      // t=1600 ms  use warm connection 4 until t=1650
			20 * time.Millisecond,  // t=1620 ms  use warm connection 5, or trigger new connection 17 (BUG: work may be discarded!)
			0,                      // t=1620 ms  use warm connection 6, or trigger new connection 18 (BUG: work may be discarded!)
			0,                      // t=1620 ms  use warm connection 7, or trigger new connection 19 (BUG: work may be discarded!)
			0,                      // t=1620 ms  use warm connection 8, or trigger new connection 20 (BUG: work may be discarded!)
			380 * time.Millisecond, // t=2020 ms  observe pool size (use 1)
			0,                      // t=2020 ms  observe pool size (use 2)
			0,                      // t=2020 ms  observe pool size (use 3)
			0,                      // t=2020 ms  observe pool size (use 4)
			0,                      // t=2020 ms  observe pool size (use 5, or dial 21)
			0,                      // t=2020 ms  observe pool size (use 6, or dial 22)
			0,                      // t=2020 ms  observe pool size (use 7, or dial 23)
			0,                      // t=2020 ms  observe pool size (use 8, or dial 24)
		}))
}

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

komuw · 2022-02-03T17:43:02Z

sounds related to #50657 somehow

bcmills · 2022-02-22T20:21:39Z

CC @neild

kassiansun · 2023-05-11T01:37:56Z

I think we can't use a dedicated context for the TLS handshake, (at least not with a simple code modification). If user doesn't use idle pool (DisableKeepAlive: true), this will make TLS handshake (within queueForDial) process un-cancellable.

Maybe we can check the connection pool for idle connection, if there're any idle connections, we can skip the dialing process, fasthttp is doing a similar process. The caveats is if the pool get occupied after the check, the call will have to wait a longer time to get an idle connection (instead of trying to dial the remote in parallel).

Another solution is adding a DialDelay option, user can choose whether they want to wait a bit longer to prioritize using the idle connection, instead of aggressively dialing the remote host. This might make the implementation a bit more efficient under some load scenarios.

jaronoff97 · 2024-06-05T15:52:05Z

Any updates here? It seems like a few things that use this as a core dependency are experiencing intermittent TLS handshake errors (i am one of those people)

mpoindexter · 2024-08-27T01:56:51Z

Is this the same thing as #59017, which was fixed in 1.23?

zhangguanzhang · 2024-09-23T01:36:55Z

any update?

toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 4, 2022

toothrot added this to the Backlog milestone Feb 4, 2022

This was referenced Mar 30, 2022

integration tests log many "http: TLS handshake error from 127.0.0.1:55336: EOF" errors kubernetes/kubernetes#109022

Open

Integration Webhook tests: TLS handshakes EOF errors kubernetes/kubernetes#109193

Closed

ritazh mentioned this issue Jul 1, 2022

TLS handshake error from: EOF open-policy-agent/gatekeeper#2142

Closed

wy65701436 mentioned this issue Dec 13, 2022

http: TLS handshake error goharbor/harbor#17924

Closed

This comment was marked as off-topic.

Sign in to view

This comment was marked as duplicate.

Sign in to view

ikyrycho mentioned this issue Apr 17, 2023

EOF error in cdi-apiserver kubevirt/containerized-data-importer#2695

Closed

seankhliao mentioned this issue May 10, 2023

net/http: Transport.getConn is wasting one connection sometimes. #60111

Closed

This was referenced Jul 12, 2023

Very large number of TLS handshakes minio/minio-go#1855

Closed

Large number of TLS handshakes to the S3 proxy buchgr/bazel-remote#675

Open

mauri870 mentioned this issue Aug 2, 2023

net/http: EOF during TLS handshake #61721

Open

erikgb mentioned this issue Oct 26, 2023

Annoying "http: TLS handshake error" in logs cybozu-go/accurate#104

Closed

4 tasks

This was referenced Jan 10, 2024

Migrate to XP ManagementPolicies crossplane-contrib/provider-kubernetes#163

Merged

TLS error logs crossplane-contrib/provider-kubernetes#175

Open

moolen mentioned this issue Jan 18, 2024

Webhook Pod outputs TLS handshake errors external-secrets/external-secrets#2983

Closed

shreyas-s-rao mentioned this issue May 9, 2024

Druid Refactor to Address Multiple Controller Conflicts gardener/etcd-druid#777

Merged

hesamhamdarsi mentioned this issue Jun 5, 2024

Receiving ssl handshake error from kubernetes APIserver and opentelemetry webhook open-telemetry/opentelemetry-operator#2956

Open

jaronoff97 mentioned this issue Jul 1, 2024

TLS handshake error in opentelemetry-operator open-telemetry/opentelemetry-helm-charts#1235

Closed

This comment was marked as duplicate.

Sign in to view

voelzmo mentioned this issue Jul 23, 2024

VPA admission controller: TLS handshake error kubernetes/autoscaler#6770

Closed

roehrich-hpe mentioned this issue Aug 2, 2024

TLS handshake EOF in conversion webhook NearNodeFlash/NearNodeFlash.github.io#192

Open

roman5595 mentioned this issue Sep 20, 2024

Kubelet TLS Handshake Failures After Certificate Rotation kubernetes/kops#16850

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: Transport wastes TLS handshake progress #50984

net/http: Transport wastes TLS handshake progress #50984

rhysh commented Feb 2, 2022

komuw commented Feb 3, 2022

bcmills commented Feb 22, 2022

This comment was marked as off-topic.

This comment was marked as off-topic.

This comment was marked as duplicate.

kassiansun commented May 11, 2023 •

edited

Loading

jaronoff97 commented Jun 5, 2024

This comment was marked as duplicate.

mpoindexter commented Aug 27, 2024

zhangguanzhang commented Sep 23, 2024

net/http: Transport wastes TLS handshake progress #50984

net/http: Transport wastes TLS handshake progress #50984

Comments

rhysh commented Feb 2, 2022

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

komuw commented Feb 3, 2022

bcmills commented Feb 22, 2022

This comment was marked as off-topic.

This comment was marked as off-topic.

This comment was marked as duplicate.

kassiansun commented May 11, 2023 • edited Loading

jaronoff97 commented Jun 5, 2024

This comment was marked as duplicate.

mpoindexter commented Aug 27, 2024

zhangguanzhang commented Sep 23, 2024

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?

kassiansun commented May 11, 2023 •

edited

Loading