net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

gopherbot · 2022-11-04T17:59:37Z

#!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

The text was updated successfully, but these errors were encountered:

gopherbot · 2022-11-04T18:00:08Z

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 · 2022-11-04T21:28:39Z

Duplicate of #55226

ZekeLu · 2022-11-09T09:31:23Z

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

gopherbot · 2022-12-14T23:56:13Z

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

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 <[email protected]> TryBot-Result: Gopher Robot <[email protected]> Run-TryBot: Damien Neil <[email protected]> Reviewed-by: Bryan Mills <[email protected]>

bcmills · 2023-02-27T19:25:59Z

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 · 2023-04-18T21:55:56Z

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

bcmills · 2024-01-09T22:14:39Z

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

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

gopherbot · 2024-01-09T22:28:58Z

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

…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 <[email protected]> LUCI-TryBot-Result: Go LUCI <[email protected]> Auto-Submit: Damien Neil <[email protected]> Reviewed-by: Emmanuel Odeke <[email protected]>

gopherbot · 2024-04-12T22:49:02Z

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

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 added this to Test Flakes Nov 4, 2022

bcmills marked this as a duplicate of #55226 Nov 4, 2022

bcmills closed this as completed Nov 4, 2022

bcmills moved this to Done in Test Flakes Nov 4, 2022

ZekeLu mentioned this issue Nov 6, 2022

net/http: TestCancelRequestWhenSharingConnection failures with nil err instead of Canceled #55226

Closed

bcmills added this to the Backlog milestone Nov 9, 2022

bcmills reopened this Nov 9, 2022

bcmills changed the title ~~net/http: unrecognized failures~~ net/http: test timeout in TestCancelRequestWhenSharingConnection Nov 9, 2022

bcmills assigned neild Nov 9, 2022

This comment was marked as resolved.

Sign in to view

bcmills mentioned this issue Feb 27, 2023

Testing packages.: unrecognized failures #57995

Closed

bcmills mentioned this issue Jan 9, 2024

net/http: unrecognized failures #65043

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

gopherbot commented Nov 4, 2022 •

edited by bcmills

Loading

gopherbot commented Nov 4, 2022

bcmills commented Nov 4, 2022

ZekeLu commented Nov 9, 2022

This comment was marked as resolved.

gopherbot commented Dec 14, 2022

bcmills commented Feb 27, 2023

gopherbot commented Apr 18, 2023

bcmills commented Jan 9, 2024

gopherbot commented Jan 9, 2024

gopherbot commented Apr 12, 2024

net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

net/http: test timeout in TestCancelRequestWhenSharingConnection #56587

Comments

gopherbot commented Nov 4, 2022 • edited by bcmills Loading

gopherbot commented Nov 4, 2022

bcmills commented Nov 4, 2022

ZekeLu commented Nov 9, 2022

This comment was marked as resolved.

gopherbot commented Dec 14, 2022

bcmills commented Feb 27, 2023

gopherbot commented Apr 18, 2023

bcmills commented Jan 9, 2024

gopherbot commented Jan 9, 2024

gopherbot commented Apr 12, 2024

gopherbot commented Nov 4, 2022 •

edited by bcmills

Loading