goproxysquid

Golang: http2 client immediately close connections via proxy while idleConn was enabled


0x00 TL;DR

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.

Not sure it's my bad code or what. The idleConn configuration was enabled on the http transport. Thanks in advance.

0x01 Environments

Code

package main

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

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

func main() {
    wg := &sync.WaitGroup{}

    wg.Add(1)
    go func() {
        doSendRequests()
        wg.Done()
    }()

    wg.Wait()
}

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, A: %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)
                    resp.Body.Close()
                } else {
                    fmt.Printf("A: %v\n", err)
                }
            }(round)
        }

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

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}
}

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

    return req
}

Env

go 1.15.3

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,direct"
GOROOT="/usr/local/go"
GOSUMDB="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"

uname -a

Linux ip-10-53-74-64.ec2.internal 4.14.243-185.433.amzn2.x86_64 #1 SMP Mon Aug 9 05:55:52 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

squid 4.15

0x02 Phenomenon

As I mentioned in the summary, 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 others and leave only one or two connections. I capture packages with Wireshark and found that the connections were closed from the client-side initially, so it may do not matter with the proxy-side, not sure about this.

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 and the idleConn configuration was enabled 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)

This could be reproduced by the latest golang 1.17.4(by now: 2021-12-05). Is there anyone who could offer a way to figure out why would this happen? Thanks.

EDIT1: all the requests done without errors.

EDIT2: I had open an issue on Golang repo, in case anyone interested: https://github.com/golang/go/issues/50000


Solution

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

    For more details, please refer to this issue: https://github.com/golang/go/issues/50000.