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

hoozecn · 2018-10-04T14:00:46Z

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

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

katiehockman · 2018-10-04T18:16:01Z

/cc @bradfitz

BruceDone · 2019-12-05T09:34:48Z

any update ? the same issue

jim-minter · 2019-12-05T19:55:05Z

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 · 2019-12-06T11:31:01Z

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 · 2019-12-06T15:08:28Z

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 · 2019-12-06T15:36:58Z

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 · 2019-12-06T20:51:44Z

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

jim-minter · 2019-12-06T21:15:20Z

@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 · 2019-12-06T21:16:07Z

Separate issue, please.

mschneider82 · 2019-12-06T21:19:16Z

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 · 2019-12-06T21:43:38Z

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

gopherbot · 2019-12-11T14:41:44Z

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

…HTTPSConnectTimeout The use of a timeout in this test caused it to be flaky: if the timeout occurred before the connection was attempted, then the Accept call on the Listener could hang indefinitely, and its goroutine would not exit until that Listener was closed. That caused the test to fail. A longer timeout would make the test less flaky, but it would become even slower and would still be sensitive to timing. Instead, replace the timeout with an explicit Context cancellation after the CONNECT request has been read. That not only ensures that the cancellation occurs at the appropriate point, but also makes the test much faster: a test run with -count=1000 now executes in less than 2s on my machine, whereas before it took upwards of 50s. Fixes #36082 Updates #28012 Change-Id: I00c20d87365fd3d257774422f39d2acc8791febd Reviewed-on: https://go-review.googlesource.com/c/go/+/210857 Run-TryBot: Bryan C. Mills <bcmills@google.com> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>

hoozecn changed the title ~~TLS connection is not closed when http proxy server doesn't response~~ TCP connection is not closed when http client make a https request via a http proxy server which doesn't response Oct 4, 2018

hoozecn changed the title ~~TCP connection is not closed when http client make a https request via a http proxy server which doesn't response~~ TCP connection is not closed after http client makes a https request via a http proxy server which doesn't response Oct 4, 2018

katiehockman added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 4, 2018

katiehockman changed the title ~~TCP connection is not closed after http client makes a https request via a http proxy server which doesn't response~~ net/http: TCP connection is not closed after http client makes a https request via a http proxy server which doesn't response Oct 4, 2018

bradfitz self-assigned this Dec 6, 2019

bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Dec 6, 2019

bradfitz added this to the Go1.14 milestone Dec 6, 2019

gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 6, 2019

gopherbot closed this as completed in 590052b Dec 9, 2019

This was referenced Dec 10, 2019

net/http: proxied connection can be spuriously closed after dialConn as of CL 210286 #36070

Closed

net/http: occasional timeouts in TestTransportProxyHTTPSConnectTimeout #36082

Closed

sthagen mentioned this issue Dec 11, 2019

net/http: use cancellation instead of a timeout in TestTransportProxy… sthagen/golang-go#76

Merged

golang locked and limited conversation to collaborators Dec 10, 2020

gopherbot added the FrozenDueToAge label Dec 10, 2020

rsc unassigned bradfitz Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

hoozecn commented Oct 4, 2018

katiehockman commented Oct 4, 2018

BruceDone commented Dec 5, 2019

jim-minter commented Dec 5, 2019

mschneider82 commented Dec 6, 2019 •

edited

jim-minter commented Dec 6, 2019 •

edited

mschneider82 commented Dec 6, 2019 •

edited

gopherbot commented Dec 6, 2019

jim-minter commented Dec 6, 2019

bradfitz commented Dec 6, 2019

mschneider82 commented Dec 6, 2019

jim-minter commented Dec 6, 2019

gopherbot commented Dec 11, 2019

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

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

Comments

hoozecn commented Oct 4, 2018

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?

katiehockman commented Oct 4, 2018

BruceDone commented Dec 5, 2019

jim-minter commented Dec 5, 2019

mschneider82 commented Dec 6, 2019 • edited

jim-minter commented Dec 6, 2019 • edited

mschneider82 commented Dec 6, 2019 • edited

gopherbot commented Dec 6, 2019

jim-minter commented Dec 6, 2019

bradfitz commented Dec 6, 2019

mschneider82 commented Dec 6, 2019

jim-minter commented Dec 6, 2019

gopherbot commented Dec 11, 2019

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

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

mschneider82 commented Dec 6, 2019 •

edited

jim-minter commented Dec 6, 2019 •

edited

mschneider82 commented Dec 6, 2019 •

edited