net/http: TCP connection is not closed after http client makes a https request via a http proxy server which doesn't response

[hoozecn]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.11 darwin/amd64

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/hoozecn/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH=":/usr/local/share/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.11/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.11/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bs/828m4j8s3035x5z5hbp_fc6m0000gn/T/go-build954257246=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I created a simple socket server which accept tcp connections without doing anything with the following code:

package main

import "net"

func main() {
	l, err := net.Listen("tcp", "0.0.0.0:12346")
	if err != nil {
		panic(err)
	}

	for {
		conn, err := l.Accept()
		if err != nil {
			panic(err)
		}

		go func() {
			_ = conn == conn
			select {}
		}()
	}
}

And create a http client with timeout

package main

import (
	"context"
	"fmt"
	"github.com/golang/glog"
	"net"
	"net/http"
	"net/url"
	"os"
	"os/exec"
	"runtime"
	"time"
)

func timerDialContext(duration time.Duration) func(ctx context.Context, network, address string) (net.Conn, error) {
	return func(ctx context.Context, network, address string) (net.Conn, error) {
		conn, err := (&net.Dialer{
			Timeout:   duration,
			KeepAlive: 0 * time.Second,
			DualStack: true,
		}).DialContext(ctx, network, address)

		if err == nil {
			//conn.SetDeadline(time.Now().Add(duration))
		}
		return conn, err
	}
}

func main() {
	client := &http.Client{Timeout: 10 * time.Second, Transport: &http.Transport{
		Proxy: func(request *http.Request) (*url.URL, error) {
			return url.Parse("http://127.0.0.1:12346")
		},
		DialContext:         timerDialContext(11 * time.Second),
		DisableKeepAlives:   true,
		TLSHandshakeTimeout: 10 * time.Second,
	}}

	//client = &http.Client{Timeout: 10 * time.Millisecond,}

	glog.Info("starting")
	req, _ := http.NewRequest("GET", "https://www.baidu.com", nil)
	req.Close = true

	resp, err := client.Do(req)
	if err != nil {
		glog.Infof("%+v", err)
	} else {
		_ = resp == resp
		resp.Body.Close()
		glog.Infof("status code %d", resp.StatusCode)
	}

	for {
		output, _ := exec.Command("lsof", "-Pn", "-p", fmt.Sprintf("%d", os.Getpid())).Output()
		glog.Info("content %s", string(output))
		buf := make([]byte, 1<<20)
		stacklen := runtime.Stack(buf, true)
		fmt.Printf("=== received SIGUSR1 ===\n*** goroutine dump...\n%s\n*** end\n", buf[:stacklen])
		time.Sleep(5 * time.Second)
	}
}

What did you expect to see?

The tcp connection to 127.0.0.1:12346 should be closed after timeout

What did you see instead?

The tcp connection stays there and a go routine leaks until the proxy server shutdown

___go_bui 24805 xxx  txt      REG                1,5    7154548 8607413808 /private/var/folders/bs/828m4j8s3035x5z5hbp_fc6m0000gn/T/___go_build_api_client_go
___go_bui 24805 xxx  txt      REG                1,5     841456 8602831466 /usr/lib/dyld
___go_bui 24805 xxx  txt      REG                1,5 1170640896 8606431345 /private/var/db/dyld/dyld_shared_cache_x86_64h
___go_bui 24805 xxx    0r     CHR               16,0        0t0       1395 /dev/ttys000
___go_bui 24805 xxx    1w     CHR               16,0        0t0       1395 /dev/ttys000
___go_bui 24805 xxx    2w     CHR               16,0      0t305       1395 /dev/ttys000
___go_bui 24805 xxx    3u   systm 0x29d17b7d192e7531        0t0            [ctl com.apple.netsrc id 9 unit 42]
___go_bui 24805 xxx    4u     CHR               15,0      0t307        580 /dev/ptmx
___go_bui 24805 xxx    5u    unix 0x29d17b7d130f5651        0t0            ->0x29d17b7d130f6c31
___go_bui 24805 xxx    6u    IPv4 0x29d17b7d1cd48cb9        0t0        TCP 127.0.0.1:56203->127.0.0.1:12346 (ESTABLISHED)
___go_bui 24805 xxx    7u  KQUEUE                                          count=0, state=0xa
___go_bui 24805 xxx    9     PIPE 0x29d17b7d0f324651      16384            ->0x29d17b7d0f323691
___go_bui 24805 xxx   11     PIPE 0x29d17b7d0f325d91      16384            ->0x29d17b7d0f324591

goroutine 38 [IO wait]:
internal/poll.runtime_pollWait(0x16ab010, 0x72, 0x23)
	/usr/local/Cellar/go/1.11/libexec/src/runtime/netpoll.go:173 +0x5e
internal/poll.(*pollDesc).wait(0xc00012a218, 0x72, 0x13c1200, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/internal/poll/fd_poll_runtime.go:85 +0x96
internal/poll.(*pollDesc).waitRead(0xc00012a218, 0xc00013b000, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/internal/poll/fd_poll_runtime.go:90 +0x45
internal/poll.(*FD).Read(0xc00012a200, 0xc00013b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/internal/poll/fd_unix.go:169 +0x36a
net.(*netFD).Read(0xc00012a200, 0xc00013b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/net/fd_unix.go:202 +0x7a
net.(*conn).Read(0xc00009e058, 0xc00013b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/net/net.go:177 +0xb0
bufio.(*Reader).fill(0xc0000a0720)
	/usr/local/Cellar/go/1.11/libexec/src/bufio/bufio.go:100 +0x2d2
bufio.(*Reader).ReadSlice(0xc0000a0720, 0xc0000d560a, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/bufio/bufio.go:341 +0x3d6
bufio.(*Reader).ReadLine(0xc0000a0720, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/bufio/bufio.go:370 +0x91
net/textproto.(*Reader).readLineSlice(0xc0000910b0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/net/textproto/reader.go:55 +0xaf
net/textproto.(*Reader).ReadLine(0xc0000910b0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/net/textproto/reader.go:36 +0x6f
net/http.ReadResponse(0xc0000a0720, 0xc00012c200, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.11/libexec/src/net/http/response.go:155 +0x10c
net/http.(*Transport).dialConn(0xc00008ed80, 0x13c2fa0, 0xc000096008, 0xc00012a100, 0x13703dd, 0x5, 0xc0000c81c0, 0x11, 0x0, 0x0, ...)
	/usr/local/Cellar/go/1.11/libexec/src/net/http/transport.go:1306 +0x1aa2
net/http.(*Transport).getConn.func4(0xc00008ed80, 0x13c2fa0, 0xc000096008, 0xc000090ed0, 0xc0000821e0)
	/usr/local/Cellar/go/1.11/libexec/src/net/http/transport.go:999 +0x8d
created by net/http.(*Transport).getConn
	/usr/local/Cellar/go/1.11/libexec/src/net/http/transport.go:998 +0x83d

[katiehockman]

/cc @bradfitz

[BruceDone]

any update ? the same issue

[jim-minter]

I believe I'm also seeing this issue, with 1.13.4 on Linux.

With a simple client like this, and using it to make a dumb GET request to some server:

c := &http.Client{
	Timeout:   30 * time.Second,
}

If the server doesn't respond within 30 seconds, the client gets a timeout error as expected. But, Go does not close the underlying TCP connection to the server. If the client keeps retrying, unfortunately its subsequent requests get queued on the same TCP connection.

If the server doesn't close the connection, or perhaps if there's an underlying TCP connection (e.g. connectivity) break which means the client and server aren't actually communicating, the client doesn't redial to establish a new connection, at least perhaps until the local kernel socket send buffer is full, or there's a TCP keepalive timeout, or something (conjecture).

You can see this when it happens because netstat continues to show the connection, and you can see its local Recv-Q figure incrementing on each retry.

Setting DisableKeepAlives works around this problem, but it's a pretty big hammer.

IMO it would make more sense for Go to abandon and close the underlying TCP connection if an HTTP timeout has occured on it.

@bradfitz @katiehockman any thoughts?

[mschneider82]

Same issure here with go 1.13.5, tcp connection is not closed, even when i use the new http.NewRequestWithContext with timeout. Setting DisableKeepAlives to true solves this for me

[jim-minter]

I also tried messing around with casting the returned error to a net.Error, checking for err.Timeout() and calling http.Client.CloseIdleConnections() in that case. It's not really a workaround either - it's intrusive and sort of helps a bit but not conclusively.

[mschneider82]

Setting req.Close = true also solves the problem for me. I don't use a shared Transport.

It really depends on the server connecting to. When the HTTPD is a golang http server (i.e caddy) we get the issue that the tcp connections are never closed. When i connect to a haproxy or something else it gets closed (maybe also from server side). Maybe it's also related to HTTP2

I will now set req.Close = true to be sure it gets closed.

I can reproduce this via this code and this http destination:

package main

import (
	"context"
	"crypto/tls"
	"log"
	"net/http"
	"os/exec"
	"runtime"
	"time"
)

func main() {
	httpReq := func() {
		ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
		defer cancel()
		req, _ := http.NewRequestWithContext(ctx, "GET", "https://www.wck.biz", nil)
		//req.Close = true        <-- this fixes this issue. But is it really needed?
		tr := &http.Transport{
			TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
		}
		client := &http.Client{
			Timeout:   10 * time.Second,
			Transport: tr,
		}
		resp, err := client.Do(req)
		if err != nil {
			log.Printf("%+v", err)
			return
		} else {
			_ = resp
			resp.Body.Close()
			log.Printf("status code %d", resp.StatusCode)
		}
		output, _ := exec.Command("netstat", "-an").Output()
		log.Printf("netstat content: %s", string(output))
		buf := make([]byte, 1<<20)
		stacklen := runtime.Stack(buf, true)
		log.Printf("goroutine dump...\n%s\n*** end\n", buf[:stacklen])
	}

	for {
		httpReq()
		time.Sleep(5 * time.Second)
	}
}

@bradfitz any thoughts why the connection will stay open? if we change the http destianation to www.google.com it is closed fine. Shouldnt the ctx cancel close it as well?

[gopherbot]

Change https://golang.org/cl/210286 mentions this issue: net/http: don't wait indefinitely in Transport for proxy CONNECT response

[jim-minter]

@bradfitz I've confused this issue which I now realise was originally opened for proxy CONNECTs with a different but similar issue that I encountered when not using a proxy. Your CL could be good for the original issue but probably not for mine. Sorry. Should I open a separate issue or can both be dealt with here?

[bradfitz]

Separate issue, please.

[mschneider82]

I also run into this without using a proxy @jim-minter Can you link the new issue? My example code should also be there..

[jim-minter]

New issue is #36026 - thanks again and sorry for the noise!

[gopherbot]

Change https://golang.org/cl/210857 mentions this issue: net/http: use cancellation instead of a timeout in TestTransportProxyHTTPSConnectTimeout