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.

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

crypto/tls: TLS handshake timeout #44267

Closed
moeen opened this issue Feb 15, 2021 · 18 comments
Closed

crypto/tls: TLS handshake timeout #44267

moeen opened this issue Feb 15, 2021 · 18 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone

Comments

@moeen
Copy link

moeen commented Feb 15, 2021

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

$ go version
go version go1.15.7 linux/amd64

Does this issue reproduce with the latest release?

I have tested this with Go 1.13+.

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/moein/.cache/go-build"
GOENV="/home/moein/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/moein/go/pkg/mod"
GONOPROXY="="
GONOSUMDB="="
GOOS="linux"
GOPATH="/home/moein/go"
GOPRIVATE="="
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib64/go/1.15"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib64/go/1.15/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-build173751188=/tmp/go-build -gno-record-gcc-switches"
GOROOT/bin/go version: go version go1.15.7 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.15.7
uname -sr: Linux 5.10.12-1-default
LSB Version:	n/a
Distributor ID:	openSUSE
Description:	openSUSE Tumbleweed
Release:	20210210
Codename:	n/a
/lib64/libc.so.6: GNU C Library (GNU libc) release release version 2.32 (git 0a8262a1b2).

What did you do?

I have a http.Client like this:

client := &http.Client{
	Timeout: 20 * time.Second,
	Transport: &http.Transport{
		TLSHandshakeTimeout: 10 * time.Second,
	},
}

And I send a HTTP request with:
res, err := client.Get(url)

What did you expect to see?

It should return a 2xx response without any error.

What did you see instead?

I get net/http: TLS handshake timeout.

Same URL works perfectly with curl.
I have also tried with InsecureSkipVerify: true but it didn't change anything.

@seankhliao
Copy link
Member

This isn;t enough info to investigate or reproduce the error

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Feb 15, 2021
@seankhliao seankhliao changed the title TLS timeout with Go crypto/tls: TLS handshake timeout Feb 15, 2021
@moeen
Copy link
Author

moeen commented Feb 15, 2021

The URL I'm trying to access is: https://api.kavenegar.com/v1/0/utils/getdate.json

curl -v output
*   Trying 172.67.72.69:443...
* Connected to api.kavenegar.com (172.67.72.69) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=CA; L=San Francisco; O=Cloudflare, Inc.; CN=sni.cloudflaressl.com
*  start date: Aug 10 00:00:00 2020 GMT
*  expire date: Aug 10 12:00:00 2021 GMT
*  subjectAltName: host "api.kavenegar.com" matched cert's "*.kavenegar.com"
*  issuer: C=US; O=Cloudflare, Inc.; CN=Cloudflare Inc ECC CA-3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x5581b9761e00)
> GET /v1/0/utils/getdate.json HTTP/2
> Host: api.kavenegar.com
> user-agent: curl/7.74.0
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 256)!
< HTTP/2 200 
< date: Mon, 15 Feb 2021 07:58:59 GMT
< content-type: application/json;charset=utf-8
< set-cookie: __cfduid=db8c442833a0950a337432cf944ee00ba1613375939; expires=Wed, 17-Mar-21 07:58:59 GMT; path=/; domain=.kavenegar.com; HttpOnly; SameSite=Lax
< cache-control: no-store, no-cache, must-revalidate,no-cache
< pragma: no-cache
< access-control-allow-origin: *
< access-control-allow-headers: Content-Type
< access-control-allow-method: POST, GET, OPTIONS
< cf-cache-status: DYNAMIC
< cf-request-id: 08464c3cad000016f27ea35000000001
< expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
< report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=T3UJaKwL9fgmEatX7OjGfvEyD6LmEjrQ2YouKs5Fo9UkENrdOsqt6oYvdayG9ZcIb2U%2Bqv9zeGX0FNmlkxoRp5zh77DAUxb5uyqYNl2c6%2FxBCw%3D%3D"}],"group":"cf-nel","max_age":604800}
< nel: {"report_to":"cf-nel","max_age":604800}
< server: cloudflare
< cf-ray: 621d7ca77a5916f2-FRA
< alt-svc: h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400
< 
* Connection #0 to host api.kavenegar.com left intact
{"return":{"status":200,"message":"تایید شد"},"entries":{"datetime":"27/11/1399 11:28:59 ق.ظ","year":2021,"month":2,"day":15,"hour":11,"minute":28,"second":59,"unixtime":1613388539}}

@davecheney
Copy link
Contributor

Can you tcp dump the connection made from your go code?

@davecheney
Copy link
Contributor

Also, does the timeout occur when you use the default http transport?

@moeen
Copy link
Author

moeen commented Feb 15, 2021

Also, does the timeout occur when you use the default http transport?

Yes. It does not change.

@moeen
Copy link
Author

moeen commented Feb 15, 2021

Also It only occurs with some Internet Providers.

@moeen
Copy link
Author

moeen commented Feb 15, 2021

Can you tcp dump the connection made from your go code?

sudo tcpdump -i wlp5s0 port 443 -w capture
capture.zip

@davecheney
Copy link
Contributor

This pcap is talking to a different host, 104.26.10.226, than the curl conversation your provided before. Are you sure they’re the same?

@moeen
Copy link
Author

moeen commented Feb 15, 2021

This pcap is talking to a different host, 104.26.10.226, than the curl conversation your provided before. Are you sure they’re the same?

It might be related to Cloudflare. Now curl is also using the same IP:

curl -v output
*   Trying 104.26.10.226:443...
*   Trying 2606:4700:20::ac43:4845:443...
* Immediate connect fail for 2606:4700:20::ac43:4845: Network is unreachable
*   Trying 2606:4700:20::681a:ae2:443...
* Immediate connect fail for 2606:4700:20::681a:ae2: Network is unreachable
*   Trying 2606:4700:20::681a:be2:443...
* Immediate connect fail for 2606:4700:20::681a:be2: Network is unreachable
* Connected to api.kavenegar.com (104.26.10.226) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=CA; L=San Francisco; O=Cloudflare, Inc.; CN=sni.cloudflaressl.com
*  start date: Aug 10 00:00:00 2020 GMT
*  expire date: Aug 10 12:00:00 2021 GMT
*  subjectAltName: host "api.kavenegar.com" matched cert's "*.kavenegar.com"
*  issuer: C=US; O=Cloudflare, Inc.; CN=Cloudflare Inc ECC CA-3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55e5489ede00)
> GET /v1/0/utils/getdate.json HTTP/2
> Host: api.kavenegar.com
> user-agent: curl/7.74.0
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 256)!
< HTTP/2 200 
< date: Mon, 15 Feb 2021 08:25:14 GMT
< content-type: application/json;charset=utf-8
< set-cookie: __cfduid=d3edb3684e8b20f35337dcfb489fef6e31613377514; expires=Wed, 17-Mar-21 08:25:14 GMT; path=/; domain=.kavenegar.com; HttpOnly; SameSite=Lax
< cache-control: no-store, no-cache, must-revalidate,no-cache
< pragma: no-cache
< access-control-allow-origin: *
< access-control-allow-headers: Content-Type
< access-control-allow-method: POST, GET, OPTIONS
< cf-cache-status: DYNAMIC
< cf-request-id: 084664449c0000325c3f002000000001
< expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
< report-to: {"max_age":604800,"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report?s=KAOxy2XKu%2BvOPcY1ccX8rgoFbGKZnBKrO9udwfz5rwHc7QUn7gaUCgPnmJ%2FGiKqe0nRKbd4CQsOGxUf2sxIQEmWUkZqayhiOJKsLVh1IvOetBw%3D%3D"}],"group":"cf-nel"}
< nel: {"max_age":604800,"report_to":"cf-nel"}
< server: cloudflare
< cf-ray: 621da31a9e56325c-FRA
< alt-svc: h3-27=":443"; ma=86400, h3-28=":443"; ma=86400, h3-29=":443"; ma=86400
< 
* Connection #0 to host api.kavenegar.com left intact
{"return":{"status":200,"message":"تایید شد"},"entries":{"datetime":"15/02/2021 11:55:06 ق.ظ","year":2021,"month":2,"day":15,"hour":11,"minute":55,"second":6,"unixtime":1613390106}}

@davecheney
Copy link
Contributor

(~) % tcpdump -r ~/Downloads/capture
reading from file /Users/davecheney/Downloads/capture, link-type EN10MB (Ethernet)
19:16:05.022681 IP 172.20.10.4.53224 > 104.26.10.226.https: Flags [S], seq 3912068042, win 64240, options [mss 1460,sackOK,TS val 2814302166 ecr 0,nop,wscale 7], length 0
19:16:05.208290 IP 104.26.10.226.https > 172.20.10.4.53224: Flags [S.], seq 3429290968, ack 3912068043, win 65535, options [mss 1400,nop,nop,sackOK,nop,wscale 10], length 0
19:16:05.208406 IP 172.20.10.4.53224 > 104.26.10.226.https: Flags [.], ack 1, win 502, length 0
19:16:05.209020 IP 172.20.10.4.53224 > 104.26.10.226.https: Flags [P.], seq 1:288, ack 1, win 502, length 287
19:16:05.277965 IP 104.26.10.226.https > 172.20.10.4.53224: Flags [.], ack 288, win 64, length 0
19:16:15.209236 IP 172.20.10.4.53224 > 104.26.10.226.https: Flags [F.], seq 288, ack 1, win 502, length 0
19:16:15.346076 IP 104.26.10.226.https > 172.20.10.4.53224: Flags [.], ack 289, win 64, length 0

Looks like the start of a TLS session to me. Is someone MITMing your connection?

@moeen
Copy link
Author

moeen commented Feb 15, 2021

We have a high internet censorship in Iran. It might be related to that.

@davecheney
Copy link
Contributor

It's quite likely. Is there anything that you think can be done in Go to address this problem (I cannot think of anything offhand), or should we close this issue?

@moeen
Copy link
Author

moeen commented Feb 15, 2021

It's quite likely. Is there anything that you think can be done in Go to address this problem (I cannot think of anything offhand), or should we close this issue?

I think it might be a crypto/tls issue since browser and cURL are working fine.

@davecheney
Copy link
Contributor

It might been that the signature on the wire that Go emits does not look like a browser or curl, hence triggering whatever firewalls your government puts in place.

I am going to make this issue as NeedsInvestigation

@davecheney davecheney added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Feb 15, 2021
@networkimprov
Copy link

cc @FiloSottile

@hamiteza
Copy link

hamiteza commented Apr 14, 2021

@moeen
try this client:

client := &http.Client{
	Timeout: 20 * time.Second,
	Transport: &http.Transport{
		TLSHandshakeTimeout: 10 * time.Second,
                TLSClientConfig: &tls.Config{
		MinVersion: tls.VersionTLS12,
		CipherSuites: []uint16{
		          tls.TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
		          tls.TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
		          tls.TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305, // Go 1.8 only
		          tls.TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305,   // Go 1.8 only
		          tls.TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
		          tls.TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
                 },
	},
}

@Airgunster
Copy link

@moeen, checked Packet Capture you've provided, Go client reports TLS handshake timeout right after awaiting for 10 seconds (default),

No.     Time               Source                Destination           Protocol Length Delta          TCP Wnd    TCP Wnd SF In-flight  Stream #   TCP flags  Info
      1 08:16:05.022681    172.20.10.4           104.26.10.226         TCP      74     0.000000       64240                            0          ··········S· 53224 → 443 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM=1 TSval=2814302166 TSecr=0 WS=128
      2 08:16:05.208290    104.26.10.226         172.20.10.4           TCP      66     0.185609       65535                            0          ·······A··S· 443 → 53224 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1400 SACK_PERM=1 WS=1024
      3 08:16:05.208406    172.20.10.4           104.26.10.226         TCP      54     0.000116       64256      128                   0          ·······A···· 53224 → 443 [ACK] Seq=1 Ack=1 Win=64256 Len=0
      4 08:16:05.209020    172.20.10.4           104.26.10.226         TLSv1    341    0.000614       64256      128        287        0          ·······AP··· Client Hello
      5 08:16:05.277965    104.26.10.226         172.20.10.4           TCP      54     0.068945       65536      1024                  0          ·······A···· 443 → 53224 [ACK] Seq=1 Ack=288 Win=65536 Len=0
...
... <`TLSHandshakeTimeout` KICKS IN AFTER 10 SECONDS>
      6 08:16:15.209236    172.20.10.4           104.26.10.226         TCP      54     9.931271       64256      128                   0          ·······A···F 53224 → 443 [FIN, ACK] Seq=288 Ack=1 Win=64256 Len=0
      7 08:16:15.346076    104.26.10.226         172.20.10.4           TCP      54     0.136840       65536      1024                  0          ·······A···· 443 → 53224 [ACK] Seq=1 Ack=289 Win=65536 Len=0

It looks like you're hitting golang/go/issues/19561.

@seankhliao seankhliao added this to the Unplanned milestone Aug 20, 2022
@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Aug 20, 2022
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

7 participants