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

x/net/http2: TestTransportBody* flaky on android and ppc64 #34616

Closed
bcmills opened this issue Sep 30, 2019 · 10 comments
Closed

x/net/http2: TestTransportBody* flaky on android and ppc64 #34616

bcmills opened this issue Sep 30, 2019 · 10 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.15

Comments

@bcmills
Copy link
Contributor

bcmills commented Sep 30, 2019

The x/net/http2.TestTransportBody tests seem to flake with request body larger than specified content length errors at a relatively high rate on certain builders.

Examples:

CC @bradfitz @tombergan
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 30, 2019
@bcmills bcmills added this to the Go1.14 milestone Sep 30, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@jamie-digital
Copy link

I've seen the same behaviour on AWS CodeBuild, which is probably amd64.

@bcmills bcmills modified the milestones: Backlog, Go1.14 Dec 19, 2019
@bcmills
Copy link
Contributor Author

bcmills commented Dec 19, 2019

Still failing quite frequently on linux-ppc64-buildlet.

Milestoned to 1.14 via #11811.

@ceseo
Copy link
Contributor

ceseo commented Dec 19, 2019

cc @laboger

@laboger
Copy link
Contributor

laboger commented Dec 19, 2019

I see this failure intermittently on ppc64le for both power8 and 9 as well as ppc64.

It started soon after this: https://go-review.googlesource.com/c/net/+/181157, which is the change that added the test and the expected error message.

@bcmills bcmills mentioned this issue Jan 27, 2020
Closed
@bcmills
Copy link
Contributor Author

bcmills commented Feb 20, 2020

linux-ppc64-buildlet:

@bcmills
Copy link
Contributor Author

bcmills commented Feb 24, 2020 •
edited

Also on aix-ppc64, apparently:

--- FAIL: TestTransportBodyLargerThanSpecifiedContentLength_len3 (0.01s)
    transport_test.go:4519: expected http2: request body larger than specified content length, got <nil>
FAIL
FAIL	golang.org/x/net/http2	14.679s

@toothrot toothrot modified the milestones: Go1.14, Go1.15 Feb 25, 2020
@bcmills
Copy link
Contributor Author

bcmills commented Mar 11, 2020 •
edited

linux-ppc64le-buildlet:

@pmur
Copy link
Contributor

pmur commented Mar 23, 2020

I looked into this for a little bit. The test is somehow racing against the server's response to the header. It is trivial to reproduce to this by inserting a small pause before attempting to write the body.

--- FAIL: TestTransportBodyLargerThanSpecifiedContentLength_len2 (0.01s)
    server_test.go:143: Running test server at: https://127.0.0.1:43807
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport creating client conn 0xc000001500 to 127.0.0.1:43807
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824
    http2_test.go:66: 2020/03/23 14:17:16 http2: server connection from 127.0.0.1:53236 on 0xc000338000
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header ":authority" = "127.0.0.1:43807"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header ":method" = "POST"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header ":path" = "/"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header ":scheme" = "https"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header "content-length" = "2"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header "accept-encoding" = "gzip"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: wrote SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: wrote HEADERS flags=END_HEADERS stream=1 len=39
    http2_test.go:66: 2020/03/23 14:17:16 http2: server: client 127.0.0.1:53236 said hello
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: read SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport received SETTINGS len=24, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896, INITIAL_WINDOW_SIZE=1048576
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: wrote SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: read SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: wrote WINDOW_UPDATE len=4 (conn) incr=983041
    http2_test.go:66: 2020/03/23 14:17:16 http2: server read frame SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: read WINDOW_UPDATE len=4 (conn) incr=983041
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041
    http2_test.go:66: 2020/03/23 14:17:16 http2: server processing setting [ENABLE_PUSH = 0]
    http2_test.go:66: 2020/03/23 14:17:16 http2: server processing setting [INITIAL_WINDOW_SIZE = 4194304]
    http2_test.go:66: 2020/03/23 14:17:16 http2: server processing setting [MAX_HEADER_LIST_SIZE = 10485760]
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: read WINDOW_UPDATE len=4 (conn) incr=1073741824
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: wrote SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=1073741824
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: read SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport received SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: read HEADERS flags=END_HEADERS stream=1 len=39
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field ":authority" = "127.0.0.1:43807"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field ":method" = "POST"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field ":path" = "/"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field ":scheme" = "https"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field "content-length" = "2"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field "accept-encoding" = "gzip"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field "user-agent" = "Go-http-client/2.0"
    http2_test.go:66: 2020/03/23 14:17:16 http2: server read frame HEADERS flags=END_HEADERS stream=1 len=39
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: read SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: server encoding header ":status" = "200"
    http2_test.go:66: 2020/03/23 14:17:16 http2: server read frame SETTINGS flags=ACK len=0
    http2_test.go:66: 2020/03/23 14:17:16 http2: server encoding header "content-length" = "0"
    http2_test.go:66: 2020/03/23 14:17:16 http2: server encoding header "date" = "Mon, 23 Mar 2020 19:17:16 GMT"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=28
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc0003e6000: wrote RST_STREAM stream=1 len=4 ErrCode=NO_ERROR
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=28
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field ":status" = "200"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field "content-length" = "0"
    http2_test.go:66: 2020/03/23 14:17:16 http2: decoded hpack field header field "date" = "Mon, 23 Mar 2020 19:17:16 GMT"
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport received HEADERS flags=END_STREAM|END_HEADERS stream=1 len=28
    http2_test.go:66: 2020/03/23 14:17:16 http2: Framer 0xc00023e2a0: read RST_STREAM stream=1 len=4 ErrCode=NO_ERROR
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport received RST_STREAM stream=1 len=4 ErrCode=NO_ERROR
    transport_test.go:4530: expected http2: request body larger than specified content length, got <nil> (200 OK)
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport closing idle conn 0xc000001500 (forSingleUse=false, maxStream=1)
    http2_test.go:66: 2020/03/23 14:17:16 http2: Transport readFrame error on conn 0xc000001500: (*net.OpError) read tcp 127.0.0.1:53236->127.0.0.1:43807: use of closed network connection

@ianlancetaylor
Copy link
Contributor

2020-05-13T18:57:01-a91f071/dragonfly-amd64
2020-05-13T18:57:01-a91f071/linux-ppc64-buildlet
2020-05-13T18:57:01-a91f071/linux-ppc64le-buildlet
2020-05-13T18:57:01-a91f071/linux-ppc64le-power9osu
2020-05-13T18:57:01-a91f071/netbsd-386-9_0
2020-05-05T04:18:28-1ed2336/android-amd64-emu
2020-05-05T04:18:28-1ed2336/linux-ppc64-buildlet
2020-05-05T04:18:28-1ed2336/linux-ppc64le-buildlet
2020-05-05T04:18:28-1ed2336/linux-ppc64le-power9osu
2020-05-01T05:30:45-e0ff5e5/linux-ppc64-buildlet
2020-05-01T05:30:45-e0ff5e5/linux-ppc64le-buildlet
2020-05-01T05:30:45-e0ff5e5/linux-ppc64le-power9osu
2020-04-25T23:01:54-ff2c4b7/android-amd64-emu
2020-04-25T23:01:54-ff2c4b7/linux-amd64
2020-04-25T23:01:54-ff2c4b7/linux-ppc64-buildlet
2020-04-25T23:01:54-ff2c4b7/linux-ppc64le-buildlet
2020-04-25T23:01:54-ff2c4b7/linux-ppc64le-power9osu
2020-04-25T23:01:54-ff2c4b7/netbsd-386-9_0
2020-04-21T23:12:49-e086a09/android-386-emu
2020-04-21T23:12:49-e086a09/linux-amd64-jessie
2020-04-21T23:12:49-e086a09/linux-ppc64-buildlet
2020-04-21T23:12:49-e086a09/linux-ppc64le-buildlet
2020-04-21T23:12:49-e086a09/linux-ppc64le-power9osu
2020-03-24T14:37:07-d3edc99/android-amd64-emu
2020-03-24T14:37:07-d3edc99/linux-amd64-sid
2020-03-24T14:37:07-d3edc99/linux-ppc64-buildlet
2020-03-24T14:37:07-d3edc99/linux-ppc64le-buildlet
2020-03-24T14:37:07-d3edc99/linux-ppc64le-power9osu
2020-03-24T14:37:07-d3edc99/netbsd-386-9_0
2020-03-24T14:37:07-d3edc99/netbsd-amd64-9_0
2020-03-20T22:07:50-118fecf/android-386-emu
2020-03-20T22:07:50-118fecf/linux-ppc64-buildlet
2020-03-20T22:07:50-118fecf/linux-ppc64le-buildlet
2020-03-20T22:07:50-118fecf/linux-ppc64le-power9osu
2020-03-20T18:12:08-1c781a1/linux-ppc64-buildlet
2020-03-20T18:12:08-1c781a1/linux-ppc64le-power9osu
2020-03-19T23:41:17-63522db/android-amd64-emu
2020-03-19T23:41:17-63522db/linux-amd64-jessie
2020-03-19T23:41:17-63522db/linux-ppc64-buildlet
2020-03-19T23:41:17-63522db/linux-ppc64le-buildlet
2020-03-19T23:41:17-63522db/linux-ppc64le-power9osu
2020-03-01T02:21:30-244492d/linux-amd64-clang

@gopherbot
Copy link

Change https://golang.org/cl/234523 mentions this issue: http2: read request in TestTransportBodyLargerThanXXX

@golang golang locked and limited conversation to collaborators May 20, 2021
dteh pushed a commit to dteh/fhttp that referenced this issue Jun 22, 2022
@ianlancetaylor
http2: read request in TestTransportBodyLargerThanXXX
3e73a77 
Otherwise the server can stop the connection before
clientStream.writeRequestBody has a chance to see if there is any more
data beyond the specified content length.

Tested by adding time.Sleep(time.Millisecond) to chunkReader.Read,
which caused the test to reliably fail before this change,
and reliably pass afterward.

Fixes golang/go#34616

Change-Id: I119bdf01bf916b2ded2c5d293655cba2596c0166
Reviewed-on: https://go-review.googlesource.com/c/net/+/234523
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.15
Development

No branches or pull requests
9 participants
@toothrot @rsc @ianlancetaylor @bcmills @ceseo @gopherbot @laboger @pmur @jamie-digital