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.

Sign up for GitHub

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: test timeout in TestCancelRequestWhenSharingConnection #56587

Open
gopherbot opened this issue Nov 4, 2022 · 10 comments
Open

net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

gopherbot opened this issue Nov 4, 2022 · 10 comments
Assignees
@neild
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@gopherbot
Copy link

gopherbot commented Nov 4, 2022 •
edited by bcmills 

#!watchflakes
post <- pkg == "net/http" && (test == "TestCancelRequestWhenSharingConnection" || log ~ `^\s+TestCancelRequestWhenSharingConnection.* \(\d+m.*\)`) && log ~ `panic: test timed out`

Issue created automatically to collect these failures.

Example (log):

2022/11/03 23:02:53 http2: server: error reading preface from client 127.0.0.1:36996: bogus greeting "CONNECT golang.fake.tld:"
2022/11/03 23:02:53 http2: server: error reading preface from client 127.0.0.1:58574: bogus greeting "CONNECT golang.fake.tld:"
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:42806: write tcp 127.0.0.1:33837->127.0.0.1:42806: i/o timeout
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:60338: EOF
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:51204: EOF
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54592: read tcp 127.0.0.1:33065->127.0.0.1:54592: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54594: read tcp 127.0.0.1:33065->127.0.0.1:54594: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54588: read tcp 127.0.0.1:33065->127.0.0.1:54588: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54602: read tcp 127.0.0.1:33065->127.0.0.1:54602: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54586: read tcp 127.0.0.1:33065->127.0.0.1:54586: use of closed network connection
...
panic: test timed out after 3m0s
running tests:
	TestCancelRequestWhenSharingConnection (2m58s)
	TestCancelRequestWhenSharingConnection/h1 (2m57s)

goroutine 24537 [running]:
panic({0x841b80, 0xc000612370})
	/tmp/workdir-host-linux-amd64-wsl/go/src/runtime/panic.go:987 +0x3bb fp=0xc000694f10 sp=0xc000694e50 pc=0x437ebb
testing.(*M).startAlarm.func1()
	/tmp/workdir-host-linux-amd64-wsl/go/src/testing/testing.go:2223 +0x3b9 fp=0xc000694fe0 sp=0xc000694f10 pc=0x503259
runtime.goexit()
	/tmp/workdir-host-linux-amd64-wsl/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000694fe8 sp=0xc000694fe0 pc=0x46d041
created by time.goFunc
	/tmp/workdir-host-linux-amd64-wsl/go/src/time/sleep.go:176 +0x32

— watchflakes
@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 4, 2022
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == ""
2022-11-03 15:18 linux-amd64-wsl go@a367981b net/http (log) 
2022/11/03 23:02:53 http2: server: error reading preface from client 127.0.0.1:36996: bogus greeting "CONNECT golang.fake.tld:"
2022/11/03 23:02:53 http2: server: error reading preface from client 127.0.0.1:58574: bogus greeting "CONNECT golang.fake.tld:"
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:42806: write tcp 127.0.0.1:33837->127.0.0.1:42806: i/o timeout
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:60338: EOF
2022/11/03 23:02:53 http: TLS handshake error from 127.0.0.1:51204: EOF
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54592: read tcp 127.0.0.1:33065->127.0.0.1:54592: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54594: read tcp 127.0.0.1:33065->127.0.0.1:54594: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54588: read tcp 127.0.0.1:33065->127.0.0.1:54588: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54602: read tcp 127.0.0.1:33065->127.0.0.1:54602: use of closed network connection
2022/11/03 23:02:54 http: TLS handshake error from 127.0.0.1:54586: read tcp 127.0.0.1:33065->127.0.0.1:54586: use of closed network connection
...
panic: test timed out after 3m0s
running tests:
	TestCancelRequestWhenSharingConnection (2m58s)
	TestCancelRequestWhenSharingConnection/h1 (2m57s)

goroutine 24537 [running]:
panic({0x841b80, 0xc000612370})
	/tmp/workdir-host-linux-amd64-wsl/go/src/runtime/panic.go:987 +0x3bb fp=0xc000694f10 sp=0xc000694e50 pc=0x437ebb
testing.(*M).startAlarm.func1()
	/tmp/workdir-host-linux-amd64-wsl/go/src/testing/testing.go:2223 +0x3b9 fp=0xc000694fe0 sp=0xc000694f10 pc=0x503259
runtime.goexit()
	/tmp/workdir-host-linux-amd64-wsl/go/src/runtime/asm_amd64.s:1594 +0x1 fp=0xc000694fe8 sp=0xc000694fe0 pc=0x46d041
created by time.goFunc
	/tmp/workdir-host-linux-amd64-wsl/go/src/time/sleep.go:176 +0x32

— watchflakes

@bcmills
Copy link
Contributor

bcmills commented Nov 4, 2022

Duplicate of #55226

@bcmills bcmills marked this as a duplicate of #55226 Nov 4, 2022
@bcmills bcmills closed this as completed Nov 4, 2022
@ZekeLu ZekeLu mentioned this issue Nov 6, 2022
Closed
@ZekeLu
Copy link
Contributor

ZekeLu commented Nov 9, 2022 

goroutine 1956 [chan receive, 2 minutes]:
...
net/http_test.testCancelRequestWhenSharingConnection(0xc0006ada00, {0x8c95d2, 0x2})
	/tmp/workdir-host-linux-amd64-wsl/go/src/net/http/transport_test.go:6519 +0x233 fp=0xc0006a4f28 sp=0xc0006a4e78 pc=0x7fc0f3
...

go/src/net/http/transport_test.go

Lines 6493 to 6519 in 3a41094

putidlec := make(chan chan struct{})
go func() {
defer wg.Done()
ctx := httptrace.WithClientTrace(context.Background(), &httptrace.ClientTrace{
PutIdleConn: func(error) {
// Signal that the idle conn has been returned to the pool,
// and wait for the order to proceed.
ch := make(chan struct{})
putidlec <- ch
<-ch
},
})
req, _ := NewRequestWithContext(ctx, "GET", ts.URL, nil)
res, err := client.Do(req)
if err == nil {
res.Body.Close()
}
if err != nil {
t.Errorf("request 1: got err %v, want nil", err)
}
}()
// Wait for the first request to receive a response and return the
// connection to the idle pool.
r1c := <-reqc
close(r1c)
idlec := <-putidlec

Line 6519 blocks on reading from the putidlec. Which means that the PutIdleConn trace is not called.

This failure mode is different from #55226.

I think this watchflakes pattern could be updated to:

#!watchflakes
post <- pkg == "net/http" && test == "TestCancelRequestWhenSharingConnection" && "panic: test timed out"

The suggested title is: net/http: test timeout in TestCancelRequestWhenSharingConnection

@bcmills bcmills added this to the Backlog milestone Nov 9, 2022
@bcmills bcmills reopened this Nov 9, 2022
@bcmills bcmills changed the title net/http: unrecognized failures net/http: test timeout in TestCancelRequestWhenSharingConnection Nov 9, 2022
@gopherbot

This comment was marked as resolved.

Sign in to view
@gopherbot
Copy link
Author

Change https://go.dev/cl/457775 mentions this issue: net/http: improve errors in TestCancelRequestWhenSharingConnection

gopherbot pushed a commit that referenced this issue Dec 16, 2022
@neild @gopherbot
net/http: improve errors in TestCancelRequestWhenSharingConnection
f4b42f5 
Provide more information about why this test might be hanging waiting
for PutIdleConn to be called (#56587): If the round trip that should
result in PutIdleConn being invoked completes, report that to the
goroutine waiting for PutIdleConn.

For #56587

Change-Id: Ie476ea0ce4a48d2bda6b9b109f89d675a10e7e45
Reviewed-on: https://go-review.googlesource.com/c/go/+/457775
Auto-Submit: Damien Neil <dneil@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Damien Neil <dneil@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
@bcmills bcmills mentioned this issue Feb 27, 2023
Closed
@bcmills
Copy link
Contributor

bcmills commented Feb 27, 2023

There is a fresh occurrence reported in #57995 (comment), but unfortunately no extra logging as far as I can tell.

Not sure why watchflakes didn't report it here.

@gopherbot
Copy link
Author

Change https://go.dev/cl/486075 mentions this issue: net/http: improve error reporting in TestCancelRequestWhenSharingConnection

@bcmills bcmills mentioned this issue Jan 9, 2024
Closed
@bcmills
Copy link
Contributor

bcmills commented Jan 9, 2024

Another one of these reported in #65043 (comment).

That one was on release-branch.go1.20 (commit 5c38c04).

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && (test == "TestCancelRequestWhenSharingConnection" || log ~ `^\s+TestCancelRequestWhenSharingConnection.* \(\d+m.*\)`) && log ~ `panic: test timed out`
2024-01-04 22:45 darwin-amd64-13 go@5c38c049 net/http (log) 
panic: test timed out after 3m0s
running tests:
	TestCancelRequestWhenSharingConnection (2m58s)
	TestCancelRequestWhenSharingConnection/h1 (2m52s)

goroutine 21087 [running]:
panic({0x1450d60, 0xc0010840d0})
	/tmp/buildlet/go/src/runtime/panic.go:987 +0x3bb fp=0xc000603f10 sp=0xc000603e50 pc=0x103577b
testing.(*M).startAlarm.func1()
	/tmp/buildlet/go/src/testing/testing.go:2241 +0x3c5 fp=0xc000603fe0 sp=0xc000603f10 pc=0x10fdae5
runtime.goexit()
	/tmp/buildlet/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000603fe8 sp=0xc000603fe0 pc=0x106b881
created by time.goFunc
	/tmp/buildlet/go/src/time/sleep.go:176 +0x32

goroutine 2 [running]:
	goroutine running on other thread; stack unavailable
created by runtime.init.6
	/tmp/buildlet/go/src/runtime/proc.go:293 +0x25

— watchflakes

gopherbot pushed a commit that referenced this issue Mar 21, 2024
@neild @gopherbot
net/http: improve error reporting in TestCancelRequestWhenSharingConn…
7d4d71e 
…ection

Ensure that errors are reported if an HTTP request unexpectedly fails.

For #56587

Change-Id: I1adfb4fedc24d4177caf54e34c5033267e32caa6
Reviewed-on: https://go-review.googlesource.com/c/go/+/486075
Reviewed-by: Bryan Mills <bcmills@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Damien Neil <dneil@google.com>
Reviewed-by: Emmanuel Odeke <emmanuel@orijtech.com>
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && (test == "TestCancelRequestWhenSharingConnection" || log ~ `^\s+TestCancelRequestWhenSharingConnection.* \(\d+m.*\)`) && log ~ `panic: test timed out`
2024-04-03 15:35 android-386-emu go@d8392e69 net/http (log) 
panic: test timed out after 3m0s
running tests:
	Test304Responses (2m58s)
	TestBadResponseAfterReadingBody (2m58s)
	TestBidiStreamReverseProxy (2m58s)
	TestCancelRequestMidBody (2m58s)
	TestCancelRequestWhenSharingConnection (2m59s)
	TestCancelRequestWithChannel (2m59s)
	TestCancelRequestWithChannelBeforeDo_Cancel (2m59s)
	TestCancelRequestWithChannelBeforeDo_Context (2m59s)
...
	TestWriteHeader0 (2m58s)
	TestWriteHeaderNoCodeCheck (2m58s)
	TestWriteHeaderSwitchingProtocols (2m59s)
	TestZeroLengthPostAndResponse (2m59s)

goroutine 24228 [running]:
testing.(*M).startAlarm.func1()
	/workdir/go/src/testing/testing.go:2259 +0x3e1
created by time.goFunc
	/workdir/go/src/time/sleep.go:176 +0x35

— watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@neild neild

Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Test Flakes
Status: Done
Milestone
Backlog
Development

No branches or pull requests
4 participants
@neild @ZekeLu @bcmills @gopherbot