go icon indicating copy to clipboard operation
go copied to clipboard
Published 3 weeks ago • verified publisher icon golang

net/http: TestRequestWriteTransport failures with `unexpected Transfer-Encoding in request`

Open bcmills opened this issue 3 years ago • 14 comments 

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request` 

2022/04/26 00:35:58 http: TLS handshake error from 127.0.0.1:38617: EOF
--- FAIL: TestRequestWriteTransport (0.59s)
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
FAIL
FAIL	net/http	35.584

greplogs --dashboard -md -l -e 'unexpected Transfer-Encoding in request'

2022-04-25T18:06:52-8619d3b/solaris-amd64-oraclerel 2020-01-02T20:13:03-a4c579e/darwin-arm64-mn4m2zdaios

This failure rate is uncommon and has only been observed on non-first-class ports, so leaving on the Backlog for now.

bcmills avatar Apr 26 '22 16:04 bcmills

Expanding the regexp to other failure modes for this test does not reveal any additional failures:

greplogs --dashboard -md -l -e 'FAIL: TestRequestWriteTransport '

2022-04-25T18:06:52-8619d3b/solaris-amd64-oraclerel 2020-01-02T20:13:03-a4c579e/darwin-arm64-mn4m2zdaios

However, it could be that the test is racy in some way; see also #44088.

bcmills avatar Apr 26 '22 16:04 bcmills

Seen again in https://build.golang.org/log/3b5be2ef32abcf753a8c0f76e646b96da61dd36d; added a watchflakes pattern.

(CC @neild)

bcmills avatar Nov 09 '23 13:11 bcmills

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2023-10-12 23:27 linux-s390x-ibm go@ef6993f3 net/http.TestRequestWriteTransport (log) 
--- FAIL: TestRequestWriteTransport (2.42s)
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip

        0

— watchflakes

gopherbot avatar Nov 09 '23 13:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-03-20 14:19 darwin-amd64-11_0 go@db423dde net/http.TestRequestWriteTransport (log) 
--- FAIL: TestRequestWriteTransport (0.43s)
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip

        0

— watchflakes

gopherbot avatar Mar 25 '24 18:03 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-04-05 01:26 netbsd-arm-bsiegert go@2e064cf1 net/http.TestRequestWriteTransport (log) 
--- FAIL: TestRequestWriteTransport (1.20s)
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip

        0

— watchflakes

gopherbot avatar Apr 05 '24 20:04 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-05-06 21:13 linux-s390x-ibm-race go@be003bd0 net/http.TestRequestWriteTransport (log) 
--- FAIL: TestRequestWriteTransport (0.98s)
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip

        0

— watchflakes

gopherbot avatar May 07 '24 01:05 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-07-15 20:09 gotip-openbsd-riscv64 go@6948b4df net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.06s)

— watchflakes

gopherbot avatar Jul 17 '24 12:07 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-07-22 21:51 gotip-freebsd-riscv64 go@b8f83e22 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.17s)

— watchflakes

gopherbot avatar Jul 24 '24 05:07 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-08-19 20:47 gotip-openbsd-riscv64 go@d2b6bdb0 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[2]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.13s)

— watchflakes

gopherbot avatar Aug 20 '24 12:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-08-29 14:37 gotip-netbsd-arm64 go@4f852b97 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.50s)

— watchflakes

gopherbot avatar Aug 29 '24 19:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-09-11 18:11 go1.23-freebsd-riscv64 release-branch.go1.23@a74951c5 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.55s)

— watchflakes

gopherbot avatar Sep 19 '24 06:09 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2024-10-24 12:32 gotip-netbsd-arm64 go@4646556b net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.55s)

— watchflakes

gopherbot avatar Oct 24 '24 14:10 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-06-10 18:18 gotip-linux-s390x-race go@fb0c27c5 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.83s)

— watchflakes

gopherbot avatar Jun 11 '25 20:06 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-06-10 13:00 go1.25-netbsd-arm release-branch.go1.25@f18d0465 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.83s)

— watchflakes

gopherbot avatar Jun 14 '25 08:06 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-07-08 17:00 go1.23-linux-s390x-race release-branch.go1.23@0a75dd7c net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.98s)

— watchflakes

gopherbot avatar Jul 10 '25 20:07 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-08-12 05:36 gotip-linux-s390x-race go@c3135913 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.80s)

— watchflakes

gopherbot avatar Aug 12 '25 13:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-08-12 20:50 go1.25-windows-amd64-longtest release-branch.go1.25@6e676ab2 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.54s)

— watchflakes

gopherbot avatar Aug 20 '25 20:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-08-29 16:56 gotip-netbsd-arm64 go@ba9e1ddc net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (0.78s)

— watchflakes

gopherbot avatar Aug 30 '25 08:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-09-26 19:11 gotip-linux-s390x-race go@3e4540b4 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.92s)

— watchflakes

gopherbot avatar Sep 27 '25 12:09 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestRequestWriteTransport" && `unexpected Transfer-Encoding in request`
2025-10-07 18:00 go1.24-netbsd-arm64 release-branch.go1.24@c6b04dd3 net/http.TestRequestWriteTransport (log) 
=== RUN   TestRequestWriteTransport
=== PAUSE TestRequestWriteTransport
=== CONT  TestRequestWriteTransport
    requestwrite_test.go:794: test[1]: unexpected Transfer-Encoding in request: GET / HTTP/1.1
        Host: example.com
        User-Agent: Go-http-client/1.1
        Transfer-Encoding: chunked
        Accept-Encoding: gzip
        
        0
        
--- FAIL: TestRequestWriteTransport (1.00s)

— watchflakes

gopherbot avatar Oct 08 '25 23:10 gopherbot

Hard to reproduce this. Pretty sure the root cause is as follows:

When sending a request, we send a Content-Length header if we know the request body's size, and send Transfer-Encoding: chunked if we do not. If we don't know the body's size, we attempt to read one byte from the body to see if it is empty or not. We wait 200ms for this read to complete and use the chunked encoding if we can't read a byte from the body in that time. See transferWriter.probeRequestBody.

I'm pretty sure these flakes are all from times when it took more than 200ms to read a byte from an io.NopCloser(strings.NewReader("")).

neild avatar Oct 09 '25 22:10 neild

Change https://go.dev/cl/710737 mentions this issue: net/http: run TestRequestWriteTransport with fake time to avoid flakes

gopherbot avatar Oct 09 '25 22:10 gopherbot