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: TestCancelRequestWhenSharingConnection failures with nil err instead of Canceled #55226

Closed
gopherbot opened this issue Sep 20, 2022 · 10 comments
Closed

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

gopherbot opened this issue Sep 20, 2022 · 10 comments
Assignees
@neild
Labels
FrozenDueToAge 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 Sep 20, 2022 •
edited by bcmills 

#!watchflakes
post <- pkg == "net/http" && test == "TestCancelRequestWhenSharingConnection" && `got err .*, want Canceled`

Bug automatically created to track these flakes.

— 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 Sep 20, 2022
@gopherbot
Copy link
Author

gopherbot commented Sep 20, 2022 •
edited

Found new matching flaky dashboard failures for:

#!watchflakes
post <- pkg == "net/http" && test == "TestCancelRequestWhenSharingConnection"
2022-09-03 18:21 windows-arm64-10 go@a0f05823 net/http.TestCancelRequestWhenSharingConnection (log) 
--- FAIL: TestCancelRequestWhenSharingConnection (0.00s)
    transport_test.go:6524: request 2: got err <nil>, want Canceled

— watchflakes

@gopherbot gopherbot changed the title net/http: flaky TestCancelRequestWhenSharingConnection net/http: TestCancelRequestWhenSharingConnection failures Sep 20, 2022
@bcmills
Copy link
Contributor

bcmills commented Oct 26, 2022

https://storage.googleapis.com/go-build-log/1e6b7c4d/linux-amd64-unified_9f4321a1.log (a linux-amd64-unified TryBot on https://go.dev/cl/445596)

(attn @neild)

@bcmills bcmills mentioned this issue Oct 26, 2022
Closed
@bcmills bcmills added this to the Backlog milestone Oct 26, 2022
@wdvxdr1123
Copy link
Contributor

a trybot failed on https://go.dev/cl/414954 (linux-amd64-race)
https://storage.googleapis.com/go-build-log/c4a4d844/linux-amd64-race_f1e0101f.log

@ZekeLu ZekeLu mentioned this issue Oct 31, 2022
Closed
@gopherbot
Copy link
Author

Change https://go.dev/cl/446676 mentions this issue: net/http: deflake TestCancelRequestWhenSharingConnection

@bcmills
Copy link
Contributor

bcmills commented Oct 31, 2022

https://storage.googleapis.com/go-build-log/20b2f437/windows-386-2012_09808bc8.log (windows-386-2012 TryBot)

romaindoumenc pushed a commit to TroutSoftware/go that referenced this issue Nov 3, 2022
@ZekeLu @romaindoumenc
net/http: deflake TestCancelRequestWhenSharingConnection
f4ec08c 
The test sleeps for 1 millisecond to give the cancellation a moment
to take effect. This is flaky because the request can finish before
the cancellation of the context is seen. It's easy to verify by adding

    time.Sleep(2*time.Millisecond)

after https://github.com/golang/go/blob/0a6c4c87404ecb018faf002919e5d5db04c69ee2/src/net/http/transport.go#L2619.
With this modification, the test fails about 5 times out of 10 runs.

The fix is easy. We just need to block the handler of the second
request until this request is cancelled. I have verify that the
updated test can uncover the issue fixed by CL 257818.

Fixes golang#55226.

Change-Id: I81575beef1a920a2ffaa5c6a5ca70a4008bd5f94
GitHub-Last-Rev: 99cb1c2
GitHub-Pull-Request: golang#56500
Reviewed-on: https://go-review.googlesource.com/c/go/+/446676
Run-TryBot: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Damien Neil <dneil@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestCancelRequestWhenSharingConnection"
2022-10-25 20:28 windows-amd64-race go@b95ea201 net/http.TestCancelRequestWhenSharingConnection (log) 
--- FAIL: TestCancelRequestWhenSharingConnection (0.00s)
    --- FAIL: TestCancelRequestWhenSharingConnection/h1 (0.01s)
        transport_test.go:6531: request 2: got err <nil>, want Canceled
2022/10/25 20:42:14 http: TLS handshake error from 127.0.0.1:50830: read tcp 127.0.0.1:50829->127.0.0.1:50830: i/o timeout
2022/10/25 20:42:14 http: TLS handshake error from 127.0.0.1:50886: read tcp 127.0.0.1:50868->127.0.0.1:50886: use of closed network connection
2022/10/25 20:42:14 http: TLS handshake error from 127.0.0.1:50878: read tcp 127.0.0.1:50868->127.0.0.1:50878: use of closed network connection
2022/10/25 20:42:14 http2: server: error reading preface from client 127.0.0.1:50919: bogus greeting "CONNECT golang.fake.tld:"
2022/10/25 20:42:14 http2: server: error reading preface from client 127.0.0.1:50921: bogus greeting "CONNECT golang.fake.tld:"
2022/10/25 20:42:16 http: TLS handshake error from 127.0.0.1:51158: EOF
2022/10/25 20:42:16 http: TLS handshake error from 127.0.0.1:51160: EOF
2022/10/25 20:42:18 http: TLS handshake error from 127.0.0.1:51591: read tcp 127.0.0.1:51589->127.0.0.1:51591: wsarecv: An existing connection was forcibly closed by the remote host.
2022/10/25 20:42:18 http: TLS handshake error from 127.0.0.1:51594: read tcp 127.0.0.1:51592->127.0.0.1:51594: wsarecv: An established connection was aborted by the software in your host machine.
2022-10-28 23:35 linux-amd64-race go@b726b0ca net/http.TestCancelRequestWhenSharingConnection (log) 
--- FAIL: TestCancelRequestWhenSharingConnection (0.00s)
    --- FAIL: TestCancelRequestWhenSharingConnection/h1 (0.01s)
        transport_test.go:6531: request 2: got err <nil>, want Canceled
2022/10/28 23:46:30 http: TLS handshake error from 127.0.0.1:42824: write tcp 127.0.0.1:34363->127.0.0.1:42824: use of closed network connection
2022/10/28 23:46:30 http: TLS handshake error from 127.0.0.1:47998: write tcp 127.0.0.1:46017->127.0.0.1:47998: i/o timeout
2022/10/28 23:46:30 http: TLS handshake error from 127.0.0.1:55276: write tcp 127.0.0.1:44997->127.0.0.1:55276: i/o timeout
2022/10/28 23:46:30 http2: server: error reading preface from client 127.0.0.1:56470: bogus greeting "CONNECT golang.fake.tld:"
2022/10/28 23:46:30 http2: server: error reading preface from client 127.0.0.1:59580: bogus greeting "CONNECT golang.fake.tld:"
2022/10/28 23:46:31 http: TLS handshake error from 127.0.0.1:58690: EOF
2022/10/28 23:46:31 http: TLS handshake error from 127.0.0.1:38948: EOF
2022/10/28 23:46:32 http: TLS handshake error from 127.0.0.1:55176: read tcp 127.0.0.1:37285->127.0.0.1:55176: read: connection reset by peer

— watchflakes

@gopherbot gopherbot reopened this Nov 4, 2022
@bcmills bcmills mentioned this issue Nov 4, 2022
Open
@ZekeLu
Copy link
Contributor

ZekeLu commented Nov 6, 2022

2022-10-25 20:28 windows-amd64-race go@b95ea201 net/http.TestCancelRequestWhenSharingConnection (log)
2022-10-28 23:35 linux-amd64-race go@b726b0ca net/http.TestCancelRequestWhenSharingConnection (log)

These two failures happened before e943dc5 was landed on 2022-11-01. So they are not new.

The root cause of this issue is that the second request finishes before the context cancellation is seen. While the root cause of #56587 is that the first request does not finish. I think it is not a duplicate of this one, and it's better to close this one and reopen that one.

@bcmills
Copy link
Contributor

bcmills commented Nov 8, 2022

I think it is not a duplicate of this one, and it's better to close this one and reopen that one.

If they have different causes and/or symptoms, then I agree they should be tracked as separate issues, but if that's the case then the issue titles and watchflakes patterns should be updated to distinguish the two. (I don't think I have enough context to update them appropriately, but I suspect that you do — if you can suggest updated patterns I can edit the issues accordingly.)

@ZekeLu
Copy link
Contributor

ZekeLu commented Nov 9, 2022

I have commented #56587 with the suggested watchflakes patterns.

@bcmills bcmills changed the title net/http: TestCancelRequestWhenSharingConnection failures net/http: TestCancelRequestWhenSharingConnection failures with nil err instead of Canceled Nov 9, 2022
@bcmills
Copy link
Contributor

bcmills commented Nov 9, 2022

Re-closing as probably fixed by CL 446676, since the watchflakes failures still all predate that change.

@bcmills bcmills closed this as completed Nov 9, 2022
@golang golang locked and limited conversation to collaborators Nov 9, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@neild neild

Labels
FrozenDueToAge 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

Successfully merging a pull request may close this issue.

net/http: deflake TestCancelRequestWhenSharingConnection ZekeLu/go
5 participants
@neild @ZekeLu @bcmills @gopherbot @wdvxdr1123