Skip to content

/ go

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
NeedsInvestigation
Milestone
Go1.15

Comments

@bcmills
Copy link
Member

@bcmills 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 this to the Go1.14 milestone Sep 30, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@jamie-digital
Copy link

@jamie-digital jamie-digital commented Oct 21, 2019

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

@bcmills bcmills commented Dec 19, 2019

Still failing quite frequently on linux-ppc64-buildlet.

Milestoned to 1.14 via #11811.
@ceseo
Copy link
Contributor

@ceseo ceseo commented Dec 19, 2019

cc @laboger
@laboger
Copy link
Contributor

@laboger 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
Member Author

@bcmills bcmills commented Feb 20, 2020

linux-ppc64-buildlet:
@bcmills
Copy link
Member Author

@bcmills 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
Member Author

@bcmills bcmills commented Mar 11, 2020 •
edited

linux-ppc64le-buildlet:
@pmur
Copy link
Contributor

@pmur 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

@ianlancetaylor ianlancetaylor commented May 19, 2020

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

@gopherbot gopherbot commented May 19, 2020

Change https://golang.org/cl/234523 mentions this issue: http2: read request in TestTransportBodyLargerThanXXX
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation
Projects
None yet
Milestone
Go1.15
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
9 participants
@toothrot @rsc @ianlancetaylor @bcmills @ceseo @gopherbot @laboger @pmur @jamie-digital