net/http/cgi spurious failure

[rsc]

cannot reproduce

TEST FAIL net/http/cgi
gotest
rm -f _test/net/http/cgi.a
6g   -p net/http/cgi -o _gotest_.6 child.go host.go  child_test.go host_test.go
matryoshka_test.go
rm -f _test/net/http/cgi.a
gopack grc _test/net/http/cgi.a _gotest_.6 
--- FAIL: cgi.TestCopyError (5.29 seconds)
    host_test.go:372: post-conn.Close, expected child to be gone
FAIL
gotest: "./6.out" failed: exit status 1
make[1]: *** [test] Error 2
make[1]: Target `test.clean' not remade because of errors.
make: *** [net/http/cgi.test] Error 1

[bradfitz]

Comment 1:

Who hit this? what OS? tip?

[rsc]

Comment 2:

I did.  Lion amd64.  tip + some edits, but none relevant here.
Rerunning the test passed.  Thought maybe a race would be
obvious looking at the code.  If not, can mark long term or invalid.

[rsc]

Comment 3:

Got this again, running on battery on Lion.
Missing a continue?
    if tries := 0; childRunning() {
        for tries < 15 && childRunning() {
            time.Sleep(50e6 * int64(tries))
            tries++
        }
        if childRunning() {
            t.Fatalf("post-conn.Close, expected child to be gone")
        }
    }

[gopherbot]

Comment 4 by dan@rzeppa.me:

I saw this error after updating to the weekly.2011-12-02 version and running the
all.bash. I'm running OSX Lion.

[rsc]

Comment 5:

Labels changed: added priority-later, removed priority-medium.

[bradfitz]

Comment 6:

I've never seen this, and can't reproduce.
When was the last time this was seen?

[gopherbot]

Comment 7 by robert.hencke:

I can reproduce this pretty faithfully if I run gotest in a loop.
This occurs on 70e914beb409 tip, Mac OS X Lion 10.7.2, 6g.
true; while [ $? == 0 ]; do gotest; done
...
rm -f _test/net/http/cgi.a
rm -f _test/net/http/cgi.a
gopack grc _test/net/http/cgi.a _gotest_.6 
2012/01/13 07:51:00 cgi: copy error: write tcp 127.0.0.1:52104: connection reset by peer
PASS
rm -f _test/net/http/cgi.a
rm -f _test/net/http/cgi.a
gopack grc _test/net/http/cgi.a _gotest_.6 
2012/01/13 07:51:01 cgi: copy error: write tcp 127.0.0.1:52110: broken pipe
PASS
rm -f _test/net/http/cgi.a
rm -f _test/net/http/cgi.a
gopack grc _test/net/http/cgi.a _gotest_.6 
--- FAIL: cgi.TestCopyError (5.29 seconds)
    host_test.go:372: post-conn.Close, expected child to be gone
FAIL
gotest: "./6.out" failed: exit status 1
gotest: "./6.out" failed: exit status 1
If you need more information, I'm happy to help.

[bradfitz]

Comment 8:

I just saw this once (on Lion too), but I can't reproduce, even in a loop now.
Robert, if this easy for you to reproduce, could you patch in:
http://golang.org/cl/5540055
... and let me know how it fails?
We're wondering if pids are being re-used.

[gopherbot]

Comment 9 by robert.hencke:

Sure thing.  I've patched it in and will leave it running in the background.  I'll let
you know when I see something.

[gopherbot]

Comment 10 by robert.hencke:

If I remove your patch, I can reproduce it in usually under a minute.
If I apply 5540055, the problem seems to goes away.
Also, not sure if it's worth mentioning, but with 5540055 applied, the copy error is
never "connection reset by peer", but always "broken pipe".
I'll leave it running and let you know if I see anything different.

[gopherbot]

Comment 11 by robert.hencke:

I had to shuffle the timing of the call to top around a little bit to make it reproduce,
but here you go.  Hope this helps!
--- FAIL: cgi.TestCopyError (7.44 seconds)
    host_test.go:380: first top: Processes: 85 total, 3 running, 2 stuck, 80 sleeping, 368 threads 
        2012/01/14 11:34:42
        Load Avg: 0.36, 0.48, 0.52 
        CPU usage: 20.0% user, 40.0% sys, 40.0% idle 
        SharedLibs: 1740K resident, 0B data, 0B linkedit.
        MemRegions: 12309 total, 519M resident, 29M private, 276M shared.
        PhysMem: 333M wired, 865M active, 254M inactive, 1452M used, 594M free.
        VM: 226G vsize, 1092M framework vsize, 4165649(0) pageins, 369923(0) pageouts.
        Networks: packets: 2412072/4696M in, 1881496/3199M out.
        Disks: 616403/9787M read, 620225/20G written.
        
        PID    COMMAND  %CPU TIME     #TH #WQ #PORTS #MREGS RPRVT RSHRD  RSIZE  VPRVT VSIZE  PGRP  PPID  STATE    UID FAULTS COW MSGSENT MSGRECV SYSBSD SYSMACH CSW PAGEINS KPRVT KSHRD  USER        
        85879  perl5.12 0.0  00:00.02 1   0   21+    37+    900K+ 1156K+ 2096K+ 19M+  2380M+ 85877 85877 sleeping 501 781+   93+ 157+    65+     598+   119+    77+ 0       69K+  8192B+ roberthencke
    host_test.go:381: last top: Processes: 85 total, 2 running, 2 stuck, 81 sleeping, 364 threads 
        2012/01/14 11:34:48
        Load Avg: 0.33, 0.48, 0.52 
        CPU usage: 0.0% user, 55.55% sys, 44.44% idle 
        SharedLibs: 1740K resident, 0B data, 0B linkedit.
        MemRegions: 12302 total, 518M resident, 29M private, 276M shared.
        PhysMem: 329M wired, 868M active, 254M inactive, 1452M used, 596M free.
        VM: 226G vsize, 1092M framework vsize, 4165649(0) pageins, 369923(0) pageouts.
        Networks: packets: 2412075/4696M in, 1881499/3199M out.
        Disks: 616403/9787M read, 620225/20G written.
        
        PID    COMMAND  %CPU TIME     #TH #WQ #PORTS #MREGS RPRVT RSHRD  RSIZE  VPRVT VSIZE  PGRP  PPID  STATE    UID FAULTS COW MSGSENT MSGRECV SYSBSD SYSMACH CSW PAGEINS KPRVT KSHRD  USER        
        85879  perl5.12 0.0  00:00.02 1   0   21+    37+    900K+ 1156K+ 2096K+ 19M+  2380M+ 85877 85877 sleeping 501 781+   93+ 157+    65+     598+   119+    77+ 0       69K+  8192B+ roberthencke
    host_test.go:382: post-conn.Close, expected child to be gone

[bradfitz]

Comment 12:

Well, it's the same process.   It's not the pid being reused.
How is the kernel not letting it go away in all that time?  It says state "sleeping" in
both listings, which doesn't sound like it's just a zombie waiting for us to wait() on
it.

[gopherbot]

Comment 13 by robert.hencke:

Increasing the number of tries (say, to 20) seems to fix it, at least on my box.

[bradfitz]

Comment 14:

Thanks for the debugging help!
Increased with http://code.google.com/p/go/source/detail?r=c44d47cfe0a2

Status changed to Fixed.

[gopherbot]

Comment 15 by setspace:

hmm.  problems from clean build of osx lion.
i tried
    http://golang.org/doc/install.html#ctools
on a cleanly built osx/lion from scratch with xcode and save the error
     6g   -p net/http/cgi -o _gotest_.6 child.go host.go  child_test.go host_test.go 
immediately reran ./all.bash ... with no errors. 
my first guess would be a timing dependent error in the test in child_test.go
host_test.go.  
ho hum.  life is short ... go must be stable cause ken is an author.
-j