net/http: TestTransportCloseResponseBody failing on Plan 9

[0intro]

In CL 11601, TestTransportCloseResponseBody is failing on Plan 9:

--- FAIL: TestTransportCloseResponseBody (0.10s)
    transport_test.go:1587: EOF
FAIL
FAIL    net/http    19.029s
2015/06/29 01:34:18 Failed: exit status: 'go 3306: 1'

See https://storage.googleapis.com/go-build-log/10feb7f2/plan9-386_6337f8ae.log.

It only fails when TestCancelRequestWithChannelBeforeDo and TestTransportCloseResponseBody are run consecutively, but not systematically.

Only TestCancelRequestWithChannelBeforeDo:

cpu% go test -v -run TestCancelRequestWithChannelBeforeDo
=== RUN   TestCancelRequestWithChannelBeforeDo
--- PASS: TestCancelRequestWithChannelBeforeDo (0.27s)
PASS
ok      net/http    0.334s

Only TestTransportCloseResponseBody:

cpu% go test -v -run TestTransportCloseResponseBody
=== RUN   TestTransportCloseResponseBody
--- PASS: TestTransportCloseResponseBody (0.34s)
PASS
ok      net/http    0.421s

TestCancelRequestWithChannelBeforeDo and TestTransportCloseResponseBody:

cpu% go test -v -run '(TestCancelRequestWithChannelBeforeDo|TestTransportCloseResponseBody)'
=== RUN   TestCancelRequestWithChannelBeforeDo
--- PASS: TestCancelRequestWithChannelBeforeDo (0.00s)
=== RUN   TestTransportCloseResponseBody
--- FAIL: TestTransportCloseResponseBody (0.12s)
    transport_test.go:1587: EOF
FAIL
exit status: 'http.test 124221: 1'
FAIL    net/http    0.197s

Here is the stack trace:

cpu% go test -v -run '(TestCancelRequestWithChannelBeforeDo|TestTransportCloseResponseBody)'
=== RUN   TestCancelRequestWithChannelBeforeDo
--- PASS: TestCancelRequestWithChannelBeforeDo (0.01s)
=== RUN   TestTransportCloseResponseBody
--- FAIL: TestTransportCloseResponseBody (0.13s)
panic:  [recovered]
    panic: 

goroutine 9 [running]:
testing.tRunner.func1(0x106e46c0)
    /usr/go/src/testing/testing.go:449 +0x130
net/http_test.TestTransportCloseResponseBody(0x106e46c0)
    /usr/go/src/net/http/transport_test.go:1587 +0x54a
testing.tRunner(0x106e46c0, 0x5430c0)
    /usr/go/src/testing/testing.go:455 +0x8e
created by testing.RunTests
    /usr/go/src/testing/testing.go:560 +0x6e8

goroutine 1 [chan receive]:
testing.RunTests(0x42edc4, 0x542700, 0xe5, 0xe5, 0x701)
    /usr/go/src/testing/testing.go:561 +0x71a
testing.(*M).Run(0x10709f5c, 0x14669c)
    /usr/go/src/testing/testing.go:493 +0x67
net/http_test.TestMain(0x10709f5c)
    /usr/go/src/net/http/main_test.go:19 +0x20
main.main()
    net/http/_test/_testmain.go:552 +0xff

goroutine 6 [runnable]:
syscall.Syscall(0x10679d00, 0x0, 0x0, 0x0, 0xffffffff, 0x0, 0x10676080, 0x22)
    /usr/go/src/syscall/asm_plan9_386.s:22 +0x5
syscall.open(0x10679ce0, 0x12, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/syscall/zsyscall_plan9_386.go:61 +0x81
syscall.Open(0x10679ce0, 0x12, 0x0, 0x12, 0x0, 0x0)
    /usr/go/src/syscall/syscall_plan9.go:321 +0x41
os.OpenFile(0x10679ce0, 0x12, 0x0, 0x0, 0x10680dd0, 0x0, 0x0)
    /usr/go/src/os/file_plan9.go:111 +0x35c
os.Open(0x10679ce0, 0x12, 0xb, 0x0, 0x0)
    /usr/go/src/os/file.go:246 +0x44
net.(*netFD).acceptPlan9(0x106a4ac0, 0x0, 0x0, 0x0)
    /usr/go/src/net/ipsock_plan9.go:222 +0x14c
net.(*TCPListener).AcceptTCP(0x106887e8, 0x106a72c0, 0x0, 0x0)
    /usr/go/src/net/tcpsock_plan9.go:144 +0x55
net.(*TCPListener).Accept(0x106887e8, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/tcpsock_plan9.go:157 +0x5d
net/http/httptest.(*historyListener).Accept(0x10679820, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/http/httptest/server.go:48 +0x52
net/http.(*Server).Serve(0x106a4b00, 0x307695f8, 0x10679820, 0x0, 0x0)
    /usr/go/src/net/http/server.go:1820 +0x97
created by net/http/httptest.(*Server).Start
    /usr/go/src/net/http/httptest/server.go:109 +0x2cc

goroutine 10 [syscall]:
syscall.Syscall(0x10679e40, 0x0, 0x0, 0x0, 0x0, 0x10664d00, 0x42f7c4, 0x10679da0)
    /usr/go/src/syscall/asm_plan9_386.s:22 +0x5
syscall.open(0x10679e00, 0x12, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/syscall/zsyscall_plan9_386.go:61 +0x81
syscall.Open(0x10679e00, 0x12, 0x0, 0x12, 0x0, 0x0)
    /usr/go/src/syscall/syscall_plan9.go:321 +0x41
os.OpenFile(0x10679e00, 0x12, 0x0, 0x0, 0x10683dd0, 0x0, 0x0)
    /usr/go/src/os/file_plan9.go:111 +0x35c
os.Open(0x10679e00, 0x12, 0xb, 0x0, 0x0)
    /usr/go/src/os/file.go:246 +0x44
net.(*netFD).acceptPlan9(0x106a4d00, 0x0, 0x0, 0x0)
    /usr/go/src/net/ipsock_plan9.go:222 +0x14c
net.(*TCPListener).AcceptTCP(0x10688860, 0x0, 0x0, 0x0)
    /usr/go/src/net/tcpsock_plan9.go:144 +0x55
net.(*TCPListener).Accept(0x10688860, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/tcpsock_plan9.go:157 +0x5d
net/http/httptest.(*historyListener).Accept(0x10679a00, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/http/httptest/server.go:48 +0x52
net/http.(*Server).Serve(0x106a4d40, 0x307695f8, 0x10679a00, 0x0, 0x0)
    /usr/go/src/net/http/server.go:1820 +0x97
created by net/http/httptest.(*Server).Start
    /usr/go/src/net/http/httptest/server.go:109 +0x2cc

goroutine 14 [syscall]:
syscall.Syscall6(0x7, 0x10730000, 0x1000, 0xffffffff, 0xffffffff, 0x0, 0x0, 0x19, 0x10731070, 0xf90, ...)
    /usr/go/src/syscall/asm_plan9_386.s:57 +0x5
syscall.Pread(0x7, 0x10730000, 0x1000, 0x1000, 0xffffffff, 0xffffffff, 0x1cee5b, 0x0, 0x0)
    /usr/go/src/syscall/zsyscall_plan9_386.go:228 +0x72
syscall.Read(0x7, 0x10730000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/syscall/syscall_plan9.go:123 +0x54
os.(*File).read(0x106888f0, 0x10730000, 0x1000, 0x1000, 0x46230, 0x0, 0x0)
    /usr/go/src/os/file_plan9.go:248 +0x49
os.(*File).Read(0x106888f0, 0x10730000, 0x1000, 0x1000, 0x1d, 0x0, 0x0)
    /usr/go/src/os/file.go:95 +0x6e
net.(*netFD).Read(0x106a5080, 0x10730000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/net/fd_plan9.go:134 +0xf6
net.(*conn).Read(0x10688900, 0x10730000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/net/net.go:124 +0x88
net/http.(*liveSwitchReader).Read(0x106e4804, 0x10730000, 0x1000, 0x1000, 0x1073005e, 0x0, 0x0)
    /usr/go/src/net/http/server.go:219 +0x83
io.(*LimitedReader).Read(0x106a72c0, 0x10730000, 0x1000, 0x1000, 0x30769818, 0x0, 0x0)
    /usr/go/src/io/io.go:427 +0xca
bufio.(*Reader).fill(0x106a84e0)
    /usr/go/src/bufio/bufio.go:97 +0x171
bufio.(*Reader).ReadSlice(0x106a84e0, 0x1065e80a, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/bufio/bufio.go:328 +0x1b3
bufio.(*Reader).ReadLine(0x106a84e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/bufio/bufio.go:357 +0x4a
net/textproto.(*Reader).readLineSlice(0x10679d20, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/textproto/reader.go:55 +0x58
net/textproto.(*Reader).ReadLine(0x10679d20, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/net/textproto/reader.go:36 +0x38
net/http.ReadRequest(0x106a84e0, 0x106bb3b0, 0x0, 0x0)
    /usr/go/src/net/http/request.go:631 +0x99
net/http.(*conn).readRequest(0x106e47e0, 0x0, 0x0, 0x0)
    /usr/go/src/net/http/server.go:628 +0x367
net/http.(*conn).serve(0x106e47e0)
    /usr/go/src/net/http/server.go:1252 +0x7a8
created by net/http.(*Server).Serve
    /usr/go/src/net/http/server.go:1843 +0x342

goroutine 12 [syscall]:
syscall.Syscall6(0x5, 0x1072e000, 0x1000, 0xffffffff, 0xffffffff, 0x0, 0x0, 0x0, 0x1065c7eb, 0x0, ...)
    /usr/go/src/syscall/asm_plan9_386.s:57 +0x5
syscall.Pread(0x5, 0x1072e000, 0x1000, 0x1000, 0xffffffff, 0xffffffff, 0x1cee5b, 0x0, 0x0)
    /usr/go/src/syscall/zsyscall_plan9_386.go:228 +0x72
syscall.Read(0x5, 0x1072e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/syscall/syscall_plan9.go:123 +0x54
os.(*File).read(0x106888b8, 0x1072e000, 0x1000, 0x1000, 0x46230, 0x0, 0x0)
    /usr/go/src/os/file_plan9.go:248 +0x49
os.(*File).Read(0x106888b8, 0x1072e000, 0x1000, 0x1000, 0x2da300, 0x0, 0x0)
    /usr/go/src/os/file.go:95 +0x6e
net.(*netFD).Read(0x106a4fc0, 0x1072e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/net/fd_plan9.go:134 +0xf6
net.(*conn).Read(0x106888c8, 0x1072e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/go/src/net/net.go:124 +0x88
net/http.noteEOFReader.Read(0x30769680, 0x106888c8, 0x106e47ac, 0x1072e000, 0x1000, 0x1000, 0x2de180, 0x0, 0x0)
    /usr/go/src/net/http/transport.go:1352 +0x54
net/http.(*noteEOFReader).Read(0x106a71d0, 0x1072e000, 0x1000, 0x1000, 0x1, 0x0, 0x0)
    <autogenerated>:128 +0xad
bufio.(*Reader).fill(0x106a8480)
    /usr/go/src/bufio/bufio.go:97 +0x171
bufio.(*Reader).Peek(0x106a8480, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/go/src/bufio/bufio.go:132 +0xac
net/http.(*persistConn).readLoop(0x106e4780)
    /usr/go/src/net/http/transport.go:883 +0xe2
created by net/http.(*Transport).dialConn
    /usr/go/src/net/http/transport.go:692 +0xa7c

goroutine 13 [runnable]:
net/http.(*persistConn).writeLoop(0x106e4780)
    /usr/go/src/net/http/transport.go:1009 +0x302
created by net/http.(*Transport).dialConn
    /usr/go/src/net/http/transport.go:693 +0xa9c
exit status: 'http.test 124488: 2'
FAIL    net/http    0.650s

[jacobsa]

I've confirmed with printf debugging that this is due to the request from TestTransportCloseResponseBody being received by the handler set up in TestCancelRequestWithChannelBeforeDo. I haven't yet figured out why this happens, since it appears they should be on different ports.

[jacobsa]

Correction: httptest.NewServer binds to :0, so the port is irrelevant. But the handler from the first test still sees the request from the second, even though the second test issues the request only after httptest.Server.Close in the first test returns.

[jacobsa]

FYI, I worked around this in patch set 7 on the CL, so to reproduce you need to remove the plan9-specific sleep.

[0intro]

Thanks for your investigations. I'll try to figure out what's happening.