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.

Sign up for GitHub

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

Jump to bottom

net/http2: client immediately close most of connections via forward proxy even if idleConn was configured #50000

Closed
zzkcode opened this issue Dec 6, 2021 · 3 comments
Closed

net/http2: client immediately close most of connections via forward proxy even if idleConn was configured #50000

zzkcode opened this issue Dec 6, 2021 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@zzkcode
Copy link
Contributor

zzkcode commented Dec 6, 2021

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

$ go version
go version go1.15.3 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ec2-user/.cache/go-build"
GOENV="/home/ec2-user/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/ec2-user/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/ec2-user/go"
GOPRIVATE=""
GOPROXY="[https://proxy.golang.org](https://proxy.golang.org/),direct"
GOROOT="/usr/local/go"
GOSUMDB="[sum.golang.org](http://sum.golang.org/)"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build200120630=/tmp/go-build -gno-record-gcc-switches"

$ squid -v
Squid Cache: Version 3.5.20

What did you do?

I'm using Go to implement an http client and squid as a forward proxy to send requests to remote servers. Things goes well when using http/1.1 via proxy or http/1.1, http2 without proxy, however, while using http2 client via proxy, most of the connections were closed immediately and only one or two were kept. And the idleConn configuration was enabled on the http transport.

Code: https://go.dev/play/p/8gaQM-80YT8

code 
package main

import (
	"context"
	"crypto/tls"
	"fmt"
	"io"
	"io/ioutil"
	"net"
	"net/http"
	"net/url"
	"time"
)

const (
	//proxyURL = "http://{{proxy-ip}}:3128"
	proxyURL = "http://127.0.0.1:3128"
)

func main() {
	doSendRequests()
}

func doSendRequests() {
	//client := newHTTPClient(nil)
	client := newHTTPClient(proxy)

	round := 0
	for {
		round += 1
		for i := 0; i < 5; i++ {
			go func(r int) {
				start := time.Now()
				var err error
				defer func() {
					duration := time.Since(start)
					fmt.Printf("Round: %d, err: %v, duration: %v\n", r, err, duration)
				}()
				req := newRequest("https://www.google.com")
				resp, err := client.Do(req)
				if err == nil {
					io.Copy(ioutil.Discard, resp.Body)
					fmt.Printf("Resp: %v\n", resp)
					resp.Body.Close()
				} else {
					fmt.Printf("err: %v\n", err)
				}
			}(round)
		}

		time.Sleep(100 * time.Second)
	}
}

func newRequest(uri string) *http.Request {
	ctx, _ := context.WithTimeout(context.Background(), 60*time.Second)
	req, _ := http.NewRequestWithContext(ctx, "GET", uri, nil)

	return req
}

type TLSDialer struct {
	net.Dialer
}

var (
	config = &tls.Config{InsecureSkipVerify: true}
)

func (dialer *TLSDialer) DialContext(ctx context.Context, network, addr string) (net.Conn, error) {
	return tls.DialWithDialer(&dialer.Dialer, network, addr, config)
}

var (
	DefaultDialer = net.Dialer{
		Timeout:   30 * time.Second,
		KeepAlive: 30 * time.Second,
		DualStack: true,
	}

	DefaultTLSDialer = TLSDialer{DefaultDialer}
)

func proxy(req *http.Request) (*url.URL, error) {
	uri, err := url.Parse(proxyURL)
	if err != nil {
		return nil, nil
	}
	return uri, nil
}

func newHTTPClient(proxy func(*http.Request) (*url.URL, error)) *http.Client {
	t := &http.Transport{
		DialContext:           (&DefaultDialer).DialContext,
		DisableKeepAlives:     false,
		DisableCompression:    false,
		ForceAttemptHTTP2:     true,
		MaxIdleConns:          5000,
		MaxIdleConnsPerHost:   1000,
		IdleConnTimeout:       0 * time.Second,
		ExpectContinueTimeout: 1 * time.Second,
	}

	if proxy == nil {
		t.DialTLSContext = (&DefaultTLSDialer).DialContext
	} else {
		t.Proxy = proxy
		t.TLSClientConfig = &tls.Config{
			InsecureSkipVerify: true,
		}
	}

	return &http.Client{Transport: t}
}

What did you expect to see?

Connections will be kept whatever http protocol I used and with or without proxy.

What did you see instead?

Everything goes well when I'm using http/1.1 via proxy or http/1.1, http2 without proxy. However, when using http2 client via proxy, the connections will be created as many as the requests, then close most of them and leave only one or two connections. I capture packages with Wireshark and found that these connections were closed from the client-side initially. And all the requests done without errors.

Resp: &{200 OK 200 HTTP/2.0 2 0 map[Alt-Svc:[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"] Cache-Control:[private, max-age=0] Content-Type:[text/html; charset=ISO-8859-1] Date:[Mon, 06 Dec 2021 12:32:24 GMT] Expires:[-1] P3p:[CP="This is not a P3P policy! See g.co/p3phelp for more info."] Server:[gws] Set-Cookie:[1P_JAR=2021-12-06-12; expires=Wed, 05-Jan-2022 12:32:24 GMT; path=/; domain=.google.com; Secure NID=511=RZao4uhEWTQ34ZWJ6v29iBM7Tx9SpZ2dG__uM_HfeQ-tHzDwaTk8kCTtvpFYdcfkCcOfxEO-t1f4jYIQvYguR8Da_8It-6o0mCEmLse4QmiSPz8zdmUdmK2bfjwstZbB0cldcgu6qcjxIO5eSJTAFUJ1PT0tibF1a1oPYh_UwKg; expires=Tue, 07-Jun-2022 12:32:24 GMT; path=/; domain=.google.com; HttpOnly] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 0xc000324cf0 -1 [] false true map[] 0xc00029a100 0xc0002a6210}
Round: 1, err: <nil>, duration: 392.090216ms
Resp: &{200 OK 200 HTTP/2.0 2 0 map[Alt-Svc:[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"] Cache-Control:[private, max-age=0] Content-Type:[text/html; charset=ISO-8859-1] Date:[Mon, 06 Dec 2021 12:32:24 GMT] Expires:[-1] P3p:[CP="This is not a P3P policy! See g.co/p3phelp for more info."] Server:[gws] Set-Cookie:[1P_JAR=2021-12-06-12; expires=Wed, 05-Jan-2022 12:32:24 GMT; path=/; domain=.google.com; Secure NID=511=LNVUTpdX1DRb-OQRkySjdCAXA9B0QHXw4z-ABiT7ga6mtdu-xx5um3CK-TE-5Aytqd1gBliByb4gda4me9oCbeCa7fv4eNN3mpVmm0O6R4_ytEv-WiL-9NPPXPZClyoRyCtsb9XlWBruGRE__lHh6YSzdIhTaXRhsPUvLh73znI; expires=Tue, 07-Jun-2022 12:32:24 GMT; path=/; domain=.google.com; HttpOnly] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 0xc000324f00 -1 [] false true map[] 0xc00029a000 0xc0002a6210}
Round: 1, err: <nil>, duration: 479.338904ms
Resp: &{200 OK 200 HTTP/2.0 2 0 map[Alt-Svc:[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"] Cache-Control:[private, max-age=0] Content-Type:[text/html; charset=ISO-8859-1] Date:[Mon, 06 Dec 2021 12:32:24 GMT] Expires:[-1] P3p:[CP="This is not a P3P policy! See g.co/p3phelp for more info."] Server:[gws] Set-Cookie:[1P_JAR=2021-12-06-12; expires=Wed, 05-Jan-2022 12:32:24 GMT; path=/; domain=.google.com; Secure NID=511=KBqGawJgugN6SKVtVSKQOU2jLuhgMnCnixni1vQqFtD58n5x_za1BjJsVbB8MvaAgd49Mhf-NvYjl-taRTzPaT_TogA2-ZAqap69JQbRY2QMKsPQynYdroZafkcjRxRoXjg_oewEOxwd6DQEViBdMs7DgfaBzhMjVrYy5xOBrGo; expires=Tue, 07-Jun-2022 12:32:24 GMT; path=/; domain=.google.com; HttpOnly] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 0xc000202e70 -1 [] false true map[] 0xc00013c100 0xc0002a6210}
Round: 1, err: <nil>, duration: 506.22799ms
Resp: &{200 OK 200 HTTP/2.0 2 0 map[Alt-Svc:[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"] Cache-Control:[private, max-age=0] Content-Type:[text/html; charset=ISO-8859-1] Date:[Mon, 06 Dec 2021 12:32:24 GMT] Expires:[-1] P3p:[CP="This is not a P3P policy! See g.co/p3phelp for more info."] Server:[gws] Set-Cookie:[1P_JAR=2021-12-06-12; expires=Wed, 05-Jan-2022 12:32:24 GMT; path=/; domain=.google.com; Secure NID=511=fQise-Rfg8Z7K2Uryilla-XFyztkaA9_v7bUKhwLfj35uYA_8jXfNW-5t8CYDuKd4J61k2sqhNDxSe66iqgIR8BgaIyL2Vn5MbJyp9V7dgrOzq3DTSb0WFjLwpnslzqX4nLHAID9niJAGBU_K9_nRuwW9S0pFp7bDgPVTNt3mdk; expires=Tue, 07-Jun-2022 12:32:24 GMT; path=/; domain=.google.com; HttpOnly] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 0xc0004921b0 -1 [] false true map[] 0xc00013c000 0xc0002a6210}
Round: 1, err: <nil>, duration: 510.754028ms
Resp: &{200 OK 200 HTTP/2.0 2 0 map[Alt-Svc:[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"] Cache-Control:[private, max-age=0] Content-Type:[text/html; charset=ISO-8859-1] Date:[Mon, 06 Dec 2021 12:32:24 GMT] Expires:[-1] P3p:[CP="This is not a P3P policy! See g.co/p3phelp for more info."] Server:[gws] Set-Cookie:[1P_JAR=2021-12-06-12; expires=Wed, 05-Jan-2022 12:32:24 GMT; path=/; domain=.google.com; Secure NID=511=i98cf0vNW6lK7pZWH9MXWWiN5aEf-VbKrXuVr04AQYO8YRIPZq1yFpT4tOkgmtSGaRwav047HLwKgURlBImgKuvvy0H1WXpAfEHICoZ5xSMiTpRRfiGy-PjtaHSLtceuNaoE1gcaNZ4ee47NwFlLUu0I5ivv6KcadNJvjb55dxs; expires=Tue, 07-Jun-2022 12:32:24 GMT; path=/; domain=.google.com; HttpOnly] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 0xc000325050 -1 [] false true map[] 0xc00021e000 0xc0002a6210}
Round: 1, err: <nil>, duration: 536.52667ms

without proxy

// www.google.com
Every 0.5s: netstat -anop | grep '172.217'                                                                                                                             

Sat Nov 27 04:26:22 2021

tcp        0	  0 10.53.74.64:44106       172.217.0.36:443        ESTABLISHED 3110/main            keepalive (25.35/0/0)
tcp        0	  0 10.53.74.64:44378       172.217.0.36:443        ESTABLISHED 3110/main            keepalive (25.44/0/0)
tcp        0	  0 10.53.74.64:44084       172.217.0.36:443        ESTABLISHED 3110/main            keepalive (25.60/0/0)
tcp        0	  0 10.53.74.64:44374       172.217.0.36:443        ESTABLISHED 3110/main            keepalive (25.43/0/0)
tcp        0	  0 10.53.74.64:44220       172.217.0.36:443        ESTABLISHED 3110/main            keepalive (25.52/0/0)

with proxy and http/1.1

Every 0.5s: netstat -anop | grep ":3128"                                                                                                                    

Sun Dec  5 13:09:44 2021

tcp        0      0 10.53.74.64:58370       {{proxy-ip}}:3128     ESTABLISHED 26322/main           keepalive (23.70/0/0)
tcp        0      0 10.53.74.64:58366       {{proxy-ip}}:3128     ESTABLISHED 26322/main           keepalive (23.70/0/0)
tcp        0      0 10.53.74.64:58374       {{proxy-ip}}:3128     ESTABLISHED 26322/main           keepalive (23.70/0/0)
tcp        0      0 10.53.74.64:58368       {{proxy-ip}}:3128     ESTABLISHED 26322/main           keepalive (23.69/0/0)
tcp        0      0 10.53.74.64:58372       {{proxy-ip}}:3128     ESTABLISHED 26322/main           keepalive (23.70/0/0)

with proxy and http2
As shown below, the other connections were closed soon after ESTABLISHED even if idleConn configuration was configured on the http transport.

Sun Dec  5 13:19:35 UTC 2021
tcp        0    284 10.53.74.64:58414       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.20/0/0)
tcp        0    284 10.53.74.64:58416       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.19/0/0)
tcp        0    284 10.53.74.64:58410       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.19/0/0)
tcp        0    284 10.53.74.64:58412       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.19/0/0)
tcp        0    284 10.53.74.64:58418       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.19/0/0)

Sun Dec  5 13:19:35 UTC 2021
tcp        0     89 10.53.74.64:58414       {{proxy-ip}}:3128     FIN_WAIT1   -                    on (0.14/0/0)
tcp        0     89 10.53.74.64:58416       {{proxy-ip}}:3128     FIN_WAIT1   -                    on (0.14/0/0)
tcp        0    365 10.53.74.64:58410       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.14/0/0)
tcp        0     89 10.53.74.64:58412       {{proxy-ip}}:3128     FIN_WAIT1   -                    on (0.14/0/0)
tcp        0     89 10.53.74.64:58418       {{proxy-ip}}:3128     FIN_WAIT1   -                    on (0.14/0/0)

Sun Dec  5 13:19:35 UTC 2021
tcp        0      0 10.53.74.64:58414       {{proxy-ip}}:3128     TIME_WAIT   -                    timewait (59.99/0/0)
tcp        0      0 10.53.74.64:58416       {{proxy-ip}}:3128     TIME_WAIT   -                    timewait (59.99/0/0)
tcp        0     31 10.53.74.64:58410       {{proxy-ip}}:3128     ESTABLISHED 34301/main           on (0.26/0/0)
tcp        0      0 10.53.74.64:58412       {{proxy-ip}}:3128     TIME_WAIT   -                    timewait (59.99/0/0)
tcp        0      0 10.53.74.64:58418       {{proxy-ip}}:3128     TIME_WAIT   -                    timewait (59.99/0/0)

Local reproducer

I make a local reproducer and do it on my own laptop.

  1. install squid & start squid;
  2. run code.

These netstats were recored within a short time, and as we can see: http2 client connect to proxy with 5 connections(req num) and then close 4 of them and only keep one connection left.

~ netstat -an | grep '127.0.0.1.3128'
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64405        ESTABLISHED
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64404        ESTABLISHED
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64403        ESTABLISHED
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64402        ESTABLISHED
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64401        ESTABLISHED
tcp4       0      0  127.0.0.1.64403        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64405        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64404        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64402        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64401        127.0.0.1.3128         ESTABLISHED

~ netstat -an | grep '127.0.0.1.3128'
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64403        ESTABLISHED
tcp4       0      0  127.0.0.1.64403        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64401        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64405        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64404        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64402        127.0.0.1.3128         TIME_WAIT

~ netstat -an | grep '127.0.0.1.3128'
tcp4       0      0  127.0.0.1.3128         127.0.0.1.64403        ESTABLISHED
tcp4       0      0  127.0.0.1.64403        127.0.0.1.3128         ESTABLISHED
tcp4       0      0  127.0.0.1.64401        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64405        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64404        127.0.0.1.3128         TIME_WAIT
tcp4       0      0  127.0.0.1.64402        127.0.0.1.3128         TIME_WAIT

I don't know why would this happen on http2 with a forward proxy involved. Are there any suggestions to figure it out? Thanks.
@toothrot
Copy link
Contributor

toothrot commented Dec 6, 2021

#26479 may also be relevant.

@toothrot toothrot added this to the Backlog milestone Dec 6, 2021
@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 6, 2021
@zzkcode
Copy link
Contributor Author

zzkcode commented Dec 7, 2021

@toothrot Thanks for your reply.

I did search for the opening and closed issues before opening this issue. They may be related but different cases.

#26479 For this issue, it looks like go does not support http2 via proxy at all at that time, so even a single request could not be done. However, what I'm now facing is: requests can be done, but most of the connections would be closed after being established.

So maybe the situation is http2 via proxy is supported but not fully supported right now? Since it seems the only different thing I can tell is the cached conns from the user side.

I run code with GODEBUG=http2debug=2 and found only one creating client conn, and paste the entire output below.
2021-12-07_go-issue-50000_GODEBUG-http2debug-2.log

@zzkcode
Copy link
Contributor Author

zzkcode commented Dec 12, 2021 •
edited
Loading

Finally, I figure it out and everything is working as expected, so it's nothing to do with net/http2.

When using custom DialTLSContext , TLSClientConfig is ignored. However, I assumed that NextProtos on tls.Config will be set by some default value in this situation, which is a fault. So my code is always requesting http/1.1 when proxy isn't enabled and will keep as many connections as requested. This makes me feel that h2 w/o proxy is keeping connections which are actually http/1.1.

And only one connection that will be kept under http2(w/ or w/o proxy) is also as expected since it was clarified within upgradeFn:

// go 1.15.3
// h2_bundle.go:6639
func http2configureTransport(t1 *Transport) (*http2Transport, error) {
	connPool := new(http2clientConnPool)
	// ...
	upgradeFn := func(authority string, c *tls.Conn) RoundTripper {
		addr := http2authorityAddr("https", authority)
		if used, err := connPool.addConnIfNeeded(addr, t2, c); err != nil {
			go c.Close()
			return http2erringRoundTripper{err}
		} else if !used {
			// Turns out we don't need this c.
			// For example, two goroutines made requests to the same host
			// at the same time, both kicking off TCP dials. (since protocol
			// was unknown)
			go c.Close()
		}
		return t2
	}
	// ...
	return t2, nil
}

I'm going to close this issue since everything is working as expected. FYI @toothrot and please correct me if I was wrong, thanks.

@zzkcode zzkcode closed this as completed Dec 12, 2021
@golang golang locked and limited conversation to collaborators Dec 12, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
3 participants
@toothrot @gopherbot @zzkcode