net/http: TestClientTimeout_Headers_h2 fails

[alexbrainman]

Please answer these questions before submitting your issue. Thanks!

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

go version devel +0716fef Mon Dec 12 01:31:50 2016 +0000 windows/386

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

set GOARCH=386
set GOBIN=
set GOEXE=.exe
set GOHOSTARCH=386
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=c:\dev
set GORACE=
set GOROOT=c:\dev\go
set GOTOOLDIR=c:\dev\go\pkg\tool\windows_386
set GCCGO=gccgo
set GO386=
set CC=gcc
set GOGCCFLAGS=-m32 -mthreads -fmessage-length=0 -fdebug-prefix map=C:\DOCUME1\brainman\LOCALS1\Temp\go-build924022071=/tmp/go-build -gno-record-gcc-switches
set CXX=g++
set CGO_ENABLED=1
set PKG_CONFIG=pkg-config
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2

What did you do?

go test -short -run=TestClientTimeout_Headers_h2 net/http

What did you expect to see?

test pass

What did you see instead?

--- FAIL: TestClientTimeout_Headers_h2 (0.34s)
client_test.go:1302: net.Error.Timeout = false; want true
client_test.go:1305: error string = "Get https://127.0.0.1:1660: net/http: request canceled while waiting for connection"; missing timeout substring
FAIL
FAIL net/http 1.766s

This only happens sometimes.

Alex

[bradfitz]

Thanks for filing. I guess this can happen if the dial is slow. There was a change this cycle to fix some of the canceled-vs-timeout error messages. This might be fallout from that.

[bradfitz]

I've looked at this a fair bit now and can't see how it happens yet, unless your clock goes backwards (NTP updates?) after the timeout, but before this line runs:

                if resp, err = c.send(req, deadline); err != nil {
// (NTP update here-ish)
                        if !deadline.IsZero() && !time.Now().Before(deadline) {
                                err = &httpError{
                                        err:     err.Error() + " (Client.Timeout exceeded while awaiting headers)",
                                        timeout: true,
                                }
                        }
                        return nil, uerr(err)
                }

But I don't really like that theory.

How easily can you reproduce this?

[alexbrainman]

unless your clock goes backwards (NTP updates?)

I doubt. I have never seen my clock going backwards.

How easily can you reproduce this?

Easy enough. If you have some patches for me to try, I am pretty sure I can make it fail.

Alex

[bradfitz]

I doubt. I have never seen my clock going backwards.

You probably don't notice, but your operating system adjusts the system time regularly by small amounts if your clock goes slightly too slow or too fast.

[alexbrainman]

unless your clock goes backwards (NTP updates?) after the timeout, but before this line runs:

C:\dev\go\src\net\http>git diff
diff --git a/src/net/http/client.go b/src/net/http/client.go
index fe2b019..4a347c7 100644
--- a/src/net/http/client.go
+++ b/src/net/http/client.go
@@ -565,13 +565,16 @@ func (c *Client) Do(req *Request) (*Response, error) {
 
 		reqs = append(reqs, req)
 		var err error
+		t1 := time.Now()
 		if resp, err = c.send(req, deadline); err != nil {
+			t2 := time.Now()
 			if !deadline.IsZero() && !time.Now().Before(deadline) {
 				err = &httpError{
 					err:     err.Error() + " (Client.Timeout exceeded while awaiting headers)",
 					timeout: true,
 				}
 			}
+			fmt.Printf("%v\n%v\n", t1, t2)
 			return nil, uerr(err)
 		}
 

C:\dev\go\src\net\http>go test -short -run=TestClientTimeout_Headers_h2

2016-12-13 12:51:02.7341585 +1100 AEDT
2016-12-13 12:51:02.7341585 +1100 AEDT
2016/12/13 12:51:02 http: TLS handshake error from 127.0.0.1:3432: read tcp 127.
0.0.1:3431->127.0.0.1:3432: use of closed network connection
--- FAIL: TestClientTimeout_Headers_h2 (0.25s)
        client_test.go:1302: net.Error.Timeout = false; want true
        client_test.go:1305: error string = "Get https://127.0.0.1:3431: net/http: request canceled while waiting for connection"; missing timeout substring
FAIL
FAIL    net/http        1.625s

C:\dev\go\src\net\http>

Maybe I am doing it wrong. You tell me.

Alex

[bradfitz]

Oh, interesting. Maybe this is because your clock just doesn't tick enough.

Can you do the same thing except also print deadline after t1 and t2?

And change !time.Now().Before(deadline) to !t2.Before(deadline) just to be sure that's not changing.

[alexbrainman]

Can you do the same thing except also

C:\dev\go\src\net\http>git diff
diff --git a/src/net/http/client.go b/src/net/http/client.go
index fe2b019..41eef07 100644
--- a/src/net/http/client.go
+++ b/src/net/http/client.go
@@ -565,13 +565,16 @@ func (c *Client) Do(req *Request) (*Response, error) {
 
 		reqs = append(reqs, req)
 		var err error
+		t1 := time.Now()
 		if resp, err = c.send(req, deadline); err != nil {
-			if !deadline.IsZero() && !time.Now().Before(deadline) {
+			t2 := time.Now()
+			if !deadline.IsZero() && !t2.Before(deadline) {
 				err = &httpError{
 					err:     err.Error() + " (Client.Timeout exceeded while awaiting headers)",
 					timeout: true,
 				}
 			}
+			fmt.Printf("%v\n%v\n%v\n", t1, t2, deadline)
 			return nil, uerr(err)
 		}
 

C:\dev\go\src\net\http>go test -short -run=TestClientTimeout_Headers_h2 net/http

2016-12-13 14:33:10.5221213 +1100 AEDT
2016-12-13 14:33:10.5221213 +1100 AEDT
2016-12-13 14:33:10.5271213 +1100 AEDT
--- FAIL: TestClientTimeout_Headers_h2 (0.45s)
        client_test.go:1302: net.Error.Timeout = false; want true
        client_test.go:1305: error string = "Get https://127.0.0.1:1390: net/http: request canceled while waiting for connection"; missing timeout substring
FAIL
FAIL    net/http        1.969s

C:\dev\go\src\net\http>

Alex

[bradfitz]

I see. The time.Now() clock isn't advancing between the two calls (which uses _SYSTEM_TIME), but it's still timing out in 5ms because the timeout mechanisms all use the more accurate clock (_INTERRUPT_TIME).

If you change the 5ms timeout to, say, 50ms, does it become reliable?

[gopherbot]

CL https://golang.org/cl/34381 mentions this issue.