net/http: some test times out? or something fails? or some noise? #2518

rogpeppe · 2011-12-02T16:17:36Z

cd $GOROOT/src/pkg/net/http; gotest -timeout 5

6g, ubuntu 11.10, 7551fda5eeef+ tip 
(i tried weekly first)

it seems perfectly reproducible currently.

backtrace attached.

Attachments:

backtrace.txt (32768 bytes)

rogpeppe · 2011-12-02T16:38:07Z

Comment 1:

looks like the "unsolicited response" message has nothing to do with it . 
gotest -run HandlerPanic
hangs with no output.

rogpeppe · 2011-12-02T16:40:04Z

Comment 2:

a more relevant stack trace:
% gotest -v -run HandlerPanic
rm -f _test/net/http.a
rm -f _test/net/http.a
gopack grc _test/net/http.a _gotest_.6 
=== RUN http_test.TestHandlerPanic
unexpected fault address 0x3e800003d81
throw: fault
[signal 0xb code=0x0 addr=0x3e800003d81 pc=0x416e49]
goroutine 1 [chan receive]:
testing.RunTests(0x400c00, 0x73d910, 0x5e0000005e, 0x404601, 0x28, ...)
    /home/rog/go/src/pkg/testing/testing.go:255 +0x6e7
testing.Main(0x400c00, 0x73d910, 0x5e0000005e, 0x72bcf8, 0x100000001, ...)
    /home/rog/go/src/pkg/testing/testing.go:202 +0x62
main.main()
    /home/rog/go/src/pkg/net/http/_testmain.go:124 +0x91
goroutine 2 [chan receive]:
net/http.(*persistConn).roundTrip(0xf840000b40, 0xf84001af30, 0x0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/transport.go:647 +0x284
net/http.(*Transport).RoundTrip(0xf840020340, 0xf840039b00, 0x16, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/transport.go:158 +0x1ef
net/http.send(0xf840039b00, 0xf840002c60, 0xf840020340, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/client.go:123 +0x1c7
net/http.(*Client).doFollowingRedirects(0x743ff0, 0xf840039b00, 0x0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/client.go:209 +0x454
net/http.(*Client).Get(0x743ff0, 0xf840021600, 0xf800000016, 0xf84003c0f0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/client.go:166 +0xb8
net/http.Get(0xf840021600, 0xf800000016, 0xf840002fc0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/client.go:148 +0x51
/home/rog/go/src/pkg/net/http/_xtest_.testHandlerPanic(0xf840000300, 0x744100, 0x461982,
0xf840000300)
    /home/rog/go/src/pkg/net/http/serve_test.go:907 +0x1a0
/home/rog/go/src/pkg/net/http/_xtest_.TestHandlerPanic(0xf840000300, 0x25744990)
    /home/rog/go/src/pkg/net/http/serve_test.go:868 +0x2a
testing.tRunner(0xf840000300, 0x73df70, 0x0, 0x0)
    /home/rog/go/src/pkg/testing/testing.go:189 +0x41
created by testing.RunTests
    /home/rog/go/src/pkg/testing/testing.go:254 +0x6c7
goroutine 3 [syscall]:
syscall.Syscall6()
    /home/rog/go/src/pkg/syscall/asm_linux_amd64.s:40 +0x5
syscall.EpollWait(0xf800000006, 0xf840039a60, 0xa0000000a, 0xffffffff, 0xc, ...)
    /home/rog/go/src/pkg/syscall/zsyscall_linux_amd64.go:252 +0xa1
net.(*pollster).WaitFD(0xf840039a50, 0xf8400209c0, 0x0, 0x7700000007, 0x0, ...)
    /home/rog/go/src/pkg/net/fd_linux.go:141 +0xf8
net.(*pollServer).Run(0xf8400209c0, 0x0)
    /home/rog/go/src/pkg/net/fd.go:228 +0xcc
created by net.newPollServer
    /home/rog/go/src/pkg/net/newpollserver.go:35 +0x327
goroutine 4 [chan receive]:
net.(*pollServer).WaitRead(0xf8400209c0, 0xf84002c5a0, 0xf8400024b0, 0xb)
    /home/rog/go/src/pkg/net/fd.go:257 +0x52
net.(*netFD).accept(0xf84002c5a0, 0x4d0a00, 0x0, 0xf8400024b0, 0xb, ...)
    /home/rog/go/src/pkg/net/fd.go:635 +0x1e5
net.(*TCPListener).AcceptTCP(0xf84001e390, 0xf840020f00, 0x0, 0x0, 0x7fbf79df1fb0, ...)
    /home/rog/go/src/pkg/net/tcpsock_posix.go:268 +0x71
net.(*TCPListener).Accept(0xf84001e390, 0x0, 0x0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/tcpsock_posix.go:278 +0x49
net/http/httptest.(*historyListener).Accept(0xf8400215e0, 0x0, 0x0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/httptest/server.go:38 +0x67
net/http.(*Server).Serve(0xf840020a80, 0xf840020ac0, 0xf8400215e0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/http/server.go:983 +0x7a
created by net/http/httptest.(*Server).Start
    /home/rog/go/src/pkg/net/http/httptest/server.go:96 +0x1b7
goroutine 5 [chan receive]:
net.(*pollServer).WaitRead(0xf8400209c0, 0xf84002cf00, 0xf8400024b0, 0xb)
    /home/rog/go/src/pkg/net/fd.go:257 +0x52
net.(*netFD).Read(0xf84002cf00, 0xf840060000, 0x100000001000, 0xffffffff, 0xf8400024b0,
...)
    /home/rog/go/src/pkg/net/fd.go:408 +0x1f2
net.(*TCPConn).Read(0xf84001e360, 0xf840060000, 0x100000001000, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/net/tcpsock_posix.go:74 +0x95
bufio.(*Reader).fill(0xf840020b00, 0x100000000)
    /home/rog/go/src/pkg/bufio/bufio.go:101 +0x101
bufio.(*Reader).Peek(0xf840020b00, 0xf800000001, 0x0, 0x0, 0x0, ...)
    /home/rog/go/src/pkg/bufio/bufio.go:133 +0xbc
net/http.(*persistConn).readLoop(0xf840000b40, 0x0)
    /home/rog/go/src/pkg/net/http/transport.go:521 +0x97
created by net/http.(*Transport).getConn
    /home/rog/go/src/pkg/net/http/transport.go:376 +0x548
goroutine 6 [semacquire]:
sync.(*Cond).Wait(0xf840013060, 0x41534b)
    /home/rog/go/src/pkg/sync/cond.go:68 +0xaa
io.(*pipe).write(0xf840013000, 0xf84001dc00, 0x2fc00000290, 0xf800000000, 0x0, ...)
    /home/rog/go/src/pkg/io/pipe.go:87 +0x1b8
io.(*PipeWriter).Write(0xf84001e330, 0xf84001dc00, 0x2fc00000290, 0x27c, 0x0, ...)
    /home/rog/go/src/pkg/io/pipe.go:154 +0x57
log.(*Logger).Output(0xf840028000, 0x100000002, 0xf84001ca00, 0x2bf0000027c, 0x0, ...)
    /home/rog/go/src/pkg/log/log.go:159 +0x247
log.Print(0x7fbf79df1d28, 0x100000001)
    /home/rog/go/src/pkg/log/log.go:276 +0x5d
net/http._func_002(0x7fbf79df1fb0, 0x7fbf79df1100, 0x7fbf79df1fb8, 0x7fbf79df1dc8)
    /home/rog/go/src/pkg/net/http/server.go:576 +0x22f
----- stack segment boundary -----
/home/rog/go/src/pkg/net/http/_xtest_._func_044(0xf84001e318, 0xf84001e310, 0x426102,
0xf840020e40, 0xf840020e80, ...)
    /home/rog/go/src/pkg/net/http/serve_test.go:904 +0x19f
net/http.HandlerFunc.ServeHTTP(0xf840020980, 0xf840020e40, 0xf840020e80, 0xf840039f20,
0xf840020e80, ...)
    /home/rog/go/src/pkg/net/http/server.go:688 +0x3d
net/http.(*conn).serve(0xf840000a20, 0x0)
    /home/rog/go/src/pkg/net/http/server.go:654 +0x599
created by net/http.(*Server).Serve
    /home/rog/go/src/pkg/net/http/server.go:1001 +0x298
gotest: "./6.out -test.v=true -test.run=HandlerPanic" failed: exit status 2

rsc · 2011-12-05T18:19:32Z

Comment 3:

Owner changed to @bradfitz.

Status changed to Accepted.

bradfitz · 2011-12-05T19:02:08Z

Comment 4:

Russ, the unsolicited noise I believe is due to this EINVAL check being removed:
http://code.google.com/p/go/source/diff?spec=svn7c18a8ff01f7c609539faad43d95551c4b5f372a&r=9942702ebc317c9f5626af670ddfcff9e8fec37e&format=side&path=/src/pkg/net/http/transport.go&old_path=/src/pkg/net/http/transport.go&old=fbac675badb483d130ad747ddb322e6bdb%C2%A844b1d1
Do you remember why that was done?
I'll look into why this test is failing, but it seems to work for all of us and our
builders, so I'm confused.

rsc · 2011-12-05T19:08:09Z

Comment 5:

It was removed because nothing should look for os.EINVAL.
What does that mean?  What is it really trying to catch?
No one knows.
Maybe the EINVAL used to happen because something
would get closed multiple times, or read after close?
Better to identify the situation and avoid it.
Russ

bradfitz · 2011-12-05T19:56:36Z

Comment 6:

The net.Conn Read is now returning a syscall.Errno(0x16) (EINVAL) when the remote side
of the TCP connection closes while we're waiting on a read.
It used to return os.EINVAL.
We shouldn't depend on syscall.Errno(0x16) from the http package.
You also wanted to get rid of transport_windows.go in the http package.
To solve both problems, should we introduce a new error type in the net package that
http can look for?  I'd like a portable way to detect the remote side closing.

rsc · 2011-12-05T19:59:46Z

Comment 7:

How about io.EOF?

bradfitz · 2011-12-05T20:13:33Z

Comment 8:

That sounds good.  So, I went to do that in the net package, starting with adding a new
test for that case, but it already passes:
// TestReadEOF verifies that we get io.EOF from a blocking read                         
                                                      
// on a TCP connection when the remote side closes.                                     
                                                      
func TestReadEOF(t *testing.T) {
        l := localListener(t)
        defer l.Close()
        closec := make(chan bool, 1)
        go func() {
                c, err := l.Accept()
                if err != nil {
                        t.Fatalf("Accept: %v", err)
                }
                <-closec
                c.Close()
        }()
        c, err := Dial("tcp", l.Addr().String())
        if err != nil {
                t.Fatalf("Dial: %v", err)
        }
        defer c.Close()
        errc := make(chan error, 1)
        go func() {
                var buf [1]byte
                _, err := c.Read(buf[:])
                errc <- err
        }()
        closec <- true
        got := <-errc
        if got != io.EOF {
                t.Errorf("got error %v; want io.EOF", got)
        }
        t.Logf("got error %v", got)
}
... so, I'm confused.
Maybe this error only happens when we get a RST packet?

rsc · 2011-12-05T20:18:19Z

Comment 9:

Can you get a system call trace of the net/http test when it fails?

bradfitz · 2011-12-05T20:41:42Z

Comment 10:

The http tests don't fail.
This bug is a mess of different issues.  I don't even know what the OP's issue is, so
I'm taking over this bug (at least for now), to address the log spam stuff about
Unsolicited response from server.

bradfitz · 2011-12-05T21:30:43Z

Comment 11:

I think net.Conn.Read should return different error values for a clean close (io.EOF)
and a dirty RST close.

rsc · 2011-12-05T22:53:04Z

Comment 12:

I guess you could do ErrUnexpectedEOF although I don't
see the difference myself.

alexbrainman · 2011-12-06T02:49:27Z

Comment 13:

This is how I see it. And I am often wrong, but ...
There are 2 scenarios here:
1) network read completes successfully and returns 0 bytes read (EOF);
2) network read completes with error (not sure about other OSes, but on Windows you
might get many different error messages depending on situation: who closed connection,
how, where and so on).
The main question here to Brad - do you care if connection is closed because of 1) or
2)? Can you treat them in them similar fashion? If not, then why not? You then have to
decide what you are looking for in these error messages. If you just want to know
whether peer closed connection on you, I say you can't, because network will not provide
this level of details. Is user closed their browser? Is user turned their PC off? Is
user pulled their network cord out? Is ISP router turned off? Why should you care which?
Alex

bradfitz · 2011-12-08T20:21:55Z

Comment 14:

Fixed the noise (per Alex's comment #13), but I can't reproduce rogpeppe's original
crash.
Closing.

Status changed to Invalid.

rogpeppe · 2011-12-08T20:31:02Z

Comment 15:

yeah, when i update to that version again and run all.bash, i don't get the crash.
probably something in my environment.

rogpeppe added invalid labels Dec 8, 2011

rogpeppe assigned bradfitz Dec 8, 2011

golang locked and limited conversation to collaborators Jun 24, 2016

gopherbot added the FrozenDueToAge label Jun 24, 2016

rsc unassigned bradfitz Jun 22, 2022

This issue was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: some test times out? or something fails? or some noise? #2518

net/http: some test times out? or something fails? or some noise? #2518

rogpeppe commented Dec 2, 2011

rogpeppe commented Dec 2, 2011

rogpeppe commented Dec 2, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

alexbrainman commented Dec 6, 2011

bradfitz commented Dec 8, 2011

rogpeppe commented Dec 8, 2011

net/http: some test times out? or something fails? or some noise? #2518

net/http: some test times out? or something fails? or some noise? #2518

Comments

rogpeppe commented Dec 2, 2011

rogpeppe commented Dec 2, 2011

rogpeppe commented Dec 2, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

bradfitz commented Dec 5, 2011

bradfitz commented Dec 5, 2011

rsc commented Dec 5, 2011

alexbrainman commented Dec 6, 2011

bradfitz commented Dec 8, 2011

rogpeppe commented Dec 8, 2011