Skip to content

/ go

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.

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/http: the client only use one connection while downloading from the server concurrency #40944

Closed
WOo0W opened this issue Aug 21, 2020 · 20 comments
Closed

net/http: the client only use one connection while downloading from the server concurrency #40944

WOo0W opened this issue Aug 21, 2020 · 20 comments

Comments

@WOo0W
Copy link

@WOo0W WOo0W commented Aug 21, 2020

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

$ go version
go version go1.15 windows/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
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\user\AppData\Local\go-build
set GOENV=C:\Users\user\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\user\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\user\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\user\AppData\Local\Temp\go-build545182214=/tmp/go-build -gno-record-gcc-switches

What did you do?

I am downloading images from i.pximg.net with multiple goroutines.
My code:

package main

import (
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"sync"
)

func main() {
	wg := sync.WaitGroup{}
	client := &http.Client{Transport: &http.Transport{}}
	for i := 0; i < 5; i++ {
		wg.Add(1)
		go func(i int) {
			defer wg.Done()
			log.Println(i, "started")
			url := fmt.Sprintf("https://i.pximg.net/img-original/img/2019/09/13/00/14/39/76752268_p%d.jpg", i)
			// url := "http://127.0.0.1/test-http"
			req, err := http.NewRequest("GET", url, nil)
			// Set the Referer header so we will not get 403 error
			req.Header["Referer"] = []string{"https://www.pixiv.net/"}
			res, err := client.Do(req)
			if err != nil {
				log.Println(err)
				return
			}
			defer res.Body.Close()
			log.Println(i, "downloading", res.Header, res.ContentLength, res.Status)
			wr, err := io.Copy(ioutil.Discard, res.Body)
			log.Println(i, wr, err)
		}(i)
	}
	wg.Wait()
}

What did you expect to see?

The client will create 5 connections to the server and download the content.

What did you see instead?

The client created 5 connections to the server at first, but 4 connections closed immediately. Only one connection was used to transfer the data.

Output:

2020/08/21 10:46:25 4 started
2020/08/21 10:46:25 3 started
2020/08/21 10:46:25 1 started
2020/08/21 10:46:25 2 started
2020/08/21 10:46:25 0 started
2020/08/21 10:46:27 1 downloading map[Accept-Ranges:[bytes] Age:[136306] Cache-Control:[max-age=31536000] Content-Length:[618736] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 12:54:42 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f002 (second)] X-Content-Type-Options:[nosniff]] 618736 200 OK
2020/08/21 10:46:28 4 downloading map[Accept-Ranges:[bytes] Age:[136248] Cache-Control:[max-age=31536000] Content-Length:[651153] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 12:55:40 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 651153 200 OK
2020/08/21 10:46:28 2 downloading map[Accept-Ranges:[bytes] Age:[163397] Cache-Control:[max-age=31536000] Content-Length:[683337] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 05:23:11 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 683337 200 OK
2020/08/21 10:46:28 3 downloading map[Accept-Ranges:[bytes] Age:[1255] Cache-Control:[max-age=31536000] Content-Length:[594356] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Sat, 21 Aug 2021 02:25:33 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] 
Via:[http/1.1 f005 (second)] X-Content-Type-Options:[nosniff]] 594356 200 OK
2020/08/21 10:46:28 0 downloading map[Accept-Ranges:[bytes] Age:[175766] Cache-Control:[max-age=31536000] Content-Length:[5681832] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 01:57:02 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f003 (second)] X-Content-Type-Options:[nosniff]] 5681832 200 OK
2020/08/21 10:46:29 1 618736 <nil>
2020/08/21 10:46:29 4 651153 <nil>
2020/08/21 10:46:29 2 683337 <nil>
2020/08/21 10:46:29 3 594356 <nil>
2020/08/21 10:46:31 0 5681832 <nil>

Proxifier log (An app which can force other apps to use a proxy)

[08.21 10:25:31] main.exe *64 - i.pximg.net:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:25:31] main.exe *64 - i.pximg.net:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:25:31] main.exe *64 - i.pximg.net:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:25:31] main.exe *64 - i.pximg.net:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:25:31] main.exe *64 - i.pximg.net:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:25:32] main.exe *64 - i.pximg.net:443 close, 438 bytes sent, 4860 bytes (4.74 KB) received, lifetime 00:01
[08.21 10:25:32] main.exe *64 - i.pximg.net:443 close, 438 bytes sent, 4860 bytes (4.74 KB) received, lifetime 00:01
[08.21 10:25:32] main.exe *64 - i.pximg.net:443 close, 438 bytes sent, 4860 bytes (4.74 KB) received, lifetime 00:01
[08.21 10:25:32] main.exe *64 - i.pximg.net:443 close, 438 bytes sent, 4860 bytes (4.74 KB) received, lifetime 00:01
[08.21 10:25:43] main.exe *64 - i.pximg.net:443 close, 42961 bytes (41.9 KB) sent, 8263702 bytes (7.88 MB) received, lifetime 00:12

I tried to build a local server with echo to test:

...
	e.GET("/test-http", func(c echo.Context) error {
		f, err := os.Open(`test.png`)
		if err != nil {
			return err
		}
		defer f.Close()
		b := ratelimit.NewBucketWithRate(100*1024, 100*1024)
		c.Response().Header()["Content-Type"] = []string{"image/png"}
		_, err = io.Copy(c.Response(), ratelimit.Reader(f, b))
		return err
	})
...

If I changed url to the local test server:

url := "http://127.0.0.1:10233/test-http"

All 5 connections are used to download the file.
Output:

2020/08/21 10:44:49 4 started
2020/08/21 10:44:49 2 started
2020/08/21 10:44:49 0 started
2020/08/21 10:44:49 3 started
2020/08/21 10:44:49 1 started
2020/08/21 10:44:49 4 downloading map[Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:44:49 GMT] Vary:[Accept-Encoding]] -1 200 OK
2020/08/21 10:44:49 3 downloading map[Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:44:49 GMT] Vary:[Accept-Encoding]] -1 200 OK
2020/08/21 10:44:49 1 downloading map[Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:44:49 GMT] Vary:[Accept-Encoding]] -1 200 OK
2020/08/21 10:44:49 2 downloading map[Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:44:49 GMT] Vary:[Accept-Encoding]] -1 200 OK
2020/08/21 10:44:49 0 downloading map[Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:44:49 GMT] Vary:[Accept-Encoding]] -1 200 OK
2020/08/21 10:45:06 4 1894098 <nil>
2020/08/21 10:45:06 3 1894098 <nil>
2020/08/21 10:45:06 1 1894098 <nil>
2020/08/21 10:45:06 0 1894098 <nil>
2020/08/21 10:45:06 2 1894098 <nil>

image

URL https://fengshuai.oss-cn-shenzhen.aliyuncs.com/mainpage/background_home_main.png also seems fine:

[08.21 10:50:12] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:50:12] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:50:12] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:50:12] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:50:12] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 open through proxy 127.0.0.1:1081 SOCKS5
[08.21 10:50:20] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 close, 679 bytes sent, 3394688 bytes (3.23 MB) received, lifetime 00:08
[08.21 10:50:21] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 close, 679 bytes sent, 3394688 bytes (3.23 MB) received, lifetime 00:09
[08.21 10:50:32] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 close, 679 bytes sent, 3394688 bytes (3.23 MB) received, lifetime 00:20
[08.21 10:50:32] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 close, 648 bytes sent, 3394688 bytes (3.23 MB) received, lifetime 00:20
[08.21 10:50:32] main.exe *64 - fengshuai.oss-cn-shenzhen.aliyuncs.com:443 close, 648 bytes sent, 3394688 bytes (3.23 MB) received, lifetime 00:20

2020/08/21 10:50:12 4 started
2020/08/21 10:50:12 0 started
2020/08/21 10:50:12 1 started
2020/08/21 10:50:12 3 started
2020/08/21 10:50:12 2 started
2020/08/21 10:50:15 0 downloading map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[3321320] Content-Md5:[LcF8uAHYES7A9R3ikeBiZQ==] Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:50:15 GMT] Etag:["2DC17CB801D8112EC0F51DE291E06265"] Last-Modified:[Tue, 02 Jun 2020 15:28:35 GMT] Server:[AliyunOSS] X-Oss-Hash-Crc64ecma:[627351119386910532] X-Oss-Object-Type:[Normal] X-Oss-Request-Id:[5F3F36673FD43B34366CD3EA] X-Oss-Server-Time:[9] X-Oss-Storage-Class:[Standard]] 3321320 200 OK
2020/08/21 10:50:15 3 downloading map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[3321320] Content-Md5:[LcF8uAHYES7A9R3ikeBiZQ==] Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:50:15 GMT] Etag:["2DC17CB801D8112EC0F51DE291E06265"] Last-Modified:[Tue, 02 Jun 2020 15:28:35 GMT] Server:[AliyunOSS] X-Oss-Hash-Crc64ecma:[627351119386910532] X-Oss-Object-Type:[Normal] X-Oss-Request-Id:[5F3F366785D3EB3735B74BB5] X-Oss-Server-Time:[1] X-Oss-Storage-Class:[Standard]] 3321320 200 OK
2020/08/21 10:50:15 4 downloading map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[3321320] Content-Md5:[LcF8uAHYES7A9R3ikeBiZQ==] Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:50:16 GMT] Etag:["2DC17CB801D8112EC0F51DE291E06265"] Last-Modified:[Tue, 02 Jun 2020 15:28:35 GMT] Server:[AliyunOSS] X-Oss-Hash-Crc64ecma:[627351119386910532] X-Oss-Object-Type:[Normal] X-Oss-Request-Id:[5F3F366888181632352091D8] X-Oss-Server-Time:[1] X-Oss-Storage-Class:[Standard]] 3321320 200 OK
2020/08/21 10:50:16 2 downloading map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[3321320] Content-Md5:[LcF8uAHYES7A9R3ikeBiZQ==] Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:50:16 GMT] Etag:["2DC17CB801D8112EC0F51DE291E06265"] Last-Modified:[Tue, 02 Jun 2020 15:28:35 GMT] Server:[AliyunOSS] X-Oss-Hash-Crc64ecma:[627351119386910532] X-Oss-Object-Type:[Normal] X-Oss-Request-Id:[5F3F3668F0F9753636A214D4] X-Oss-Server-Time:[8] X-Oss-Storage-Class:[Standard]] 3321320 200 OK
2020/08/21 10:50:17 0 3321320 <nil>
2020/08/21 10:50:17 1 downloading map[Accept-Ranges:[bytes] Connection:[keep-alive] Content-Length:[3321320] Content-Md5:[LcF8uAHYES7A9R3ikeBiZQ==] Content-Type:[image/png] Date:[Fri, 21 Aug 2020 02:50:18 GMT] Etag:["2DC17CB801D8112EC0F51DE291E06265"] Last-Modified:[Tue, 02 Jun 2020 15:28:35 GMT] Server:[AliyunOSS] X-Oss-Hash-Crc64ecma:[627351119386910532] X-Oss-Object-Type:[Normal] X-Oss-Request-Id:[5F3F366A8338063437965BE9] X-Oss-Server-Time:[1] X-Oss-Storage-Class:[Standard]] 3321320 200 OK
2020/08/21 10:50:19 4 3321320 <nil>
2020/08/21 10:50:20 2 3321320 <nil>
2020/08/21 10:50:21 1 3321320 <nil>
2020/08/21 10:50:32 3 3321320 <nil>

I also tested i.imgur.com and pbs.twimg.com, all have same issue.
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 21, 2020 •
edited

client := &http.Client{Transport: &http.Transport{}}

What happens if you use http.DefaultClient?
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 21, 2020

client := &http.Client{Transport: &http.Transport{}}

What happens if you use http.DefaultClient?

Same issue with client := http.DefaultClient
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 21, 2020

Thank you

I am not able to reproduce the issue you reported

(~/src) % go run issue.go
2020/08/21 13:58:29 2 started
2020/08/21 13:58:29 1 started
2020/08/21 13:58:29 0 started
2020/08/21 13:58:29 3 started
2020/08/21 13:58:29 4 started
2020/08/21 13:58:31 1 downloading map[Accept-Ranges:[bytes] Age:[140628] Cache-Control:[max-age=31536000] Content-Length:[618736] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 03:58:30 GMT] Expires:[Thu, 19 Aug 2021 12:54:42 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f002 (second)] X-Content-Type-Options:[nosniff]] 618736 200 OK
2020/08/21 13:58:31 4 downloading map[Accept-Ranges:[bytes] Age:[140570] Cache-Control:[max-age=31536000] Content-Length:[651153] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 03:58:30 GMT] Expires:[Thu, 19 Aug 2021 12:55:40 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 651153 200 OK
2020/08/21 13:58:31 2 downloading map[Accept-Ranges:[bytes] Age:[167719] Cache-Control:[max-age=31536000] Content-Length:[683337] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 03:58:30 GMT] Expires:[Thu, 19 Aug 2021 05:23:11 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 683337 200 OK
2020/08/21 13:58:31 3 downloading map[Accept-Ranges:[bytes] Age:[5577] Cache-Control:[max-age=31536000] Content-Length:[594356] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 03:58:30 GMT] Expires:[Sat, 21 Aug 2021 02:25:33 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f005 (second)] X-Content-Type-Options:[nosniff]] 594356 200 OK
2020/08/21 13:58:31 0 downloading map[Accept-Ranges:[bytes] Age:[180088] Cache-Control:[max-age=31536000] Content-Length:[5681832] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 03:58:30 GMT] Expires:[Thu, 19 Aug 2021 01:57:02 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f003 (second)] X-Content-Type-Options:[nosniff]] 5681832 200 OK
2020/08/21 13:58:32 2 683337 <nil>
2020/08/21 13:58:34 4 651153 <nil>
2020/08/21 13:58:34 3 594356 <nil>
2020/08/21 13:58:34 1 618736 <nil>
2020/08/21 13:58:34 0 5681832 <nil>

Five files appear to be downloaded in parallel.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 21, 2020

Have you check the connections it actually made?
Try another big file https://dl.google.com/go/go1.15.windows-amd64.msi
My output with this url:

2020/08/21 12:11:08 4 started
2020/08/21 12:11:08 2 started
2020/08/21 12:11:08 3 started
2020/08/21 12:11:08 0 started
2020/08/21 12:11:08 1 started
2020/08/21 12:11:08 1 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:11:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:11:09 3 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:11:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:11:09 0 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:11:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:11:11 2 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:11:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:12:03 4 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:11:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:12:14 0 121090048 <nil>
Ctrl C here, only one url finished.
exit status 2

My connections downloading this file (checking with Windows Resource Monitor):
image
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 21, 2020

I'm sorry I don't have access to windows or the tools you use. On my machine I see several transfers start one after another, then complete as if they were working in parallel.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 21, 2020 •
edited

On linux or macOS you can check the connections with lsof
My case downloading https://dl.google.com/go/go1.15.windows-amd64.msi,
setting url := https://dl.google.com/go/go1.15.windows-amd64.msi (build on Windows, run on Debian 10):

$ lsof -iTCP -nP|grep http-conn
http-conn 13929       user     9u  IPv4 36907270      0t0  TCP myip:54212->203.208.43.65:443 (ESTABLISHED)

You can see only one connection is used to transfer the data.

If you are using macOS you can also use Proxifier to check it. Just set up a local http proxy and use Proxifier to proxy the go program.
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 21, 2020 •
edited

I'm sorry those commands don't work on my machine -- i don't know why.

Please understand I don't disagree that you are having a problem, but it is not clear to be that this is a problem caused by Go, not some other component between your Go program and the origin server.

Writing network downloaders is a common use case for Go and there have been no issues of this sort reported for a long time (so long I cannot remember one off hand). Again, I am not saying that you are wrong, or your problem is not happening, just that this has not been isolated to the Go http stack.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 21, 2020 •
edited

Downloading big file https://dl.google.com/go/go1.15.windows-amd64.msi on Debian 10

2020/08/21 12:47:09 0 started
2020/08/21 12:47:09 1 started
2020/08/21 12:47:09 4 started
2020/08/21 12:47:09 2 started
2020/08/21 12:47:09 3 started
2020/08/21 12:47:09 2 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:47:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:47:09 4 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:47:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:47:20 2 121090048 <nil>
2020/08/21 12:47:20 0 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:47:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:47:20 1 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:47:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:47:22 4 121090048 <nil>
2020/08/21 12:47:29 0 121090048 <nil>
2020/08/21 12:47:29 3 downloading map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Fri, 21 Aug 2020 04:47:09 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]] 121090048 200 OK
2020/08/21 12:47:35 1 121090048 <nil>
2020/08/21 12:47:42 3 121090048 <nil>

You can see it's not the same time when the header is being printed. After downloader 2 finished, downloader 0's header is printed.
You can try to slow down your Internet connection so the download will not finish so fast.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 21, 2020

It so strange that for different website I got different result.
While downloading from i.pximg.net using Python I can see 5 connections is all downloading data in Proxifier.
@networkimprov
Copy link

@networkimprov networkimprov commented Aug 22, 2020

@gopherbot remove WaitingForInfo
@qingyunha
Copy link
Contributor

@qingyunha qingyunha commented Aug 22, 2020

I can reproduce the issue. But it seems because of HTTP2.
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 22, 2020

Http2 multiplexes multiple streams over a single connection.
@networkimprov
Copy link

@networkimprov networkimprov commented Aug 22, 2020

@WOo0W have you looked at the headers for the different servers you've tried? That will give you the HTTP version.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 23, 2020 •
edited

The request to i.pximg.net:

&{Method:GET URL:https://i.pximg.net/img-original/img/2019/09/13/00/14/39/76752268_p3.jpg Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[Referer:[https://www.pixiv.net/]] Body:<nil> GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:i.pximg.net Form:map[] PostForm:map[] 
MultipartForm:<nil> Trailer:map[] RemoteAddr: RequestURI: TLS:<nil> Cancel:<nil> Response:<nil> ctx:0xc000010080}

The Proto field is HTTP/1.1

The output in the first comment of i.pximg.net:

2020/08/21 10:46:25 4 started
2020/08/21 10:46:25 3 started
2020/08/21 10:46:25 1 started
2020/08/21 10:46:25 2 started
2020/08/21 10:46:25 0 started
2020/08/21 10:46:27 1 downloading map[Accept-Ranges:[bytes] Age:[136306] Cache-Control:[max-age=31536000] Content-Length:[618736] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 12:54:42 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f002 (second)] X-Content-Type-Options:[nosniff]] 618736 200 OK
2020/08/21 10:46:28 4 downloading map[Accept-Ranges:[bytes] Age:[136248] Cache-Control:[max-age=31536000] Content-Length:[651153] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 12:55:40 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 651153 200 OK
2020/08/21 10:46:28 2 downloading map[Accept-Ranges:[bytes] Age:[163397] Cache-Control:[max-age=31536000] Content-Length:[683337] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 05:23:11 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f001 (second)] X-Content-Type-Options:[nosniff]] 683337 200 OK
2020/08/21 10:46:28 3 downloading map[Accept-Ranges:[bytes] Age:[1255] Cache-Control:[max-age=31536000] Content-Length:[594356] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Sat, 21 Aug 2021 02:25:33 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] 
Via:[http/1.1 f005 (second)] X-Content-Type-Options:[nosniff]] 594356 200 OK
2020/08/21 10:46:28 0 downloading map[Accept-Ranges:[bytes] Age:[175766] Cache-Control:[max-age=31536000] Content-Length:[5681832] Content-Type:[image/jpeg] Date:[Fri, 21 Aug 2020 02:46:28 GMT] Expires:[Thu, 19 Aug 2021 01:57:02 GMT] Last-Modified:[Thu, 12 Sep 2019 15:14:39 GMT] Server:[nginx] Via:[http/1.1 f003 (second)] X-Content-Type-Options:[nosniff]] 5681832 200 OK
2020/08/21 10:46:29 1 618736 <nil>
2020/08/21 10:46:29 4 651153 <nil>
2020/08/21 10:46:29 2 683337 <nil>
2020/08/21 10:46:29 3 594356 <nil>
2020/08/21 10:46:31 0 5681832 <nil>

The Via header is Via:[http/1.1 f003 (second)]


The request to https://dl.google.com/go/go1.15.windows-amd64.msi:

&{Method:GET URL:https://dl.google.com/go/go1.15.windows-amd64.msi Proto:HTTP/1.1 ProtoMajor:1 ProtoMinor:1 Header:map[Referer:[https://www.pixiv.net/]] Body:<nil> GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:dl.google.com Form:map[] PostForm:map[] MultipartForm:<nil> Trailer:map[] RemoteAddr: RequestURI: TLS:<nil> Cancel:<nil> Response:<nil> ctx:0xc000010080}

The response header (no HTTP version info in it):

map[Accept-Ranges:[bytes] Age:[0] Alt-Svc:[h3-29=":443"; ma=2592000,h3-27=":443"; ma=2592000,h3-T050=":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:[public,max-age=86400] Content-Disposition:[attachment] Content-Length:[121090048] Content-Security-Policy:[default-src 'none'] Content-Type:[application/x-msi] Date:[Sun, 23 Aug 2020 04:34:56 GMT] Etag:["67d747"] Last-Modified:[Tue, 11 Aug 2020 21:04:07 GMT] Server:[downloads] X-Content-Type-Options:[nosniff] X-Frame-Options:[SAMEORIGIN] X-Xss-Protection:[0]]
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 23, 2020 •
edited

But in Chrome DevTools the request verson is h2:
image
image

If this is a feature in HTTP2, how can I disable this feature in go?
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 23, 2020

If this is a feature in HTTP2, how can I disable this feature in go?

Create a new transport. For various reasons new transports are not enabled for http2 by default.
@qingyunha
Copy link
Contributor

@qingyunha qingyunha commented Aug 23, 2020

Set GODEBUG environment
GODEBUG=http2client=0 # disable HTTP/2 client support
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 23, 2020

Found in https://golang.org/pkg/net/http/

Starting with Go 1.6, the http package has transparent support for the HTTP/2 protocol when using HTTPS. Programs that must disable HTTP/2 can do so by setting Transport.TLSNextProto (for clients) or Server.TLSNextProto (for servers) to a non-nil, empty map.

After setting Transport.TLSNextProto to an empty map the client uses HTTP 1.1 and works well.
Is there any way to disable this feature on HTTP 2 without downgrading the protocol version?
@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 23, 2020

Try creating a new client for each request.
@WOo0W
Copy link
Author

@WOo0W WOo0W commented Aug 24, 2020

It works well creating a new client for each goroutine.
Thank you.
@WOo0W WOo0W closed this Aug 24, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
5 participants
@davecheney @networkimprov @qingyunha @gopherbot @WOo0W
You can’t perform that action at this time.