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

Jump to bottom

net/http: TestClientTimeout_Headers_h2 fails #18287

Closed
alexbrainman opened this issue Dec 12, 2016 · 9 comments
Closed

net/http: TestClientTimeout_Headers_h2 fails #18287

alexbrainman opened this issue Dec 12, 2016 · 9 comments
Labels
FrozenDueToAge Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone
Go1.8Maybe

Comments

@alexbrainman
Copy link
Member

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 bradfitz self-assigned this Dec 12, 2016
@bradfitz bradfitz added the Testing An issue that has been verified to require only test changes, not just a test failure. label Dec 12, 2016
@bradfitz bradfitz added this to the Go1.8Maybe milestone Dec 12, 2016
@bradfitz
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link

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

@golang golang locked and limited conversation to collaborators Dec 14, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Milestone
Go1.8Maybe
Development

No branches or pull requests
3 participants
@bradfitz @gopherbot @alexbrainman