os/exec: understand 387 fd leak

[bradfitz]

The linux-386-387 builder continues to fail somewhat regularly with:

--- FAIL: TestPipeLookPathLeak (0.07 seconds)
    exec_test.go:230: leaked 4 fds; want ~0; have:
        COMMAND    PID    USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
        exec.test 2220 gobuild  cwd    DIR  202,1     4096  288319 /tmp/gobuilder/linux-386-387-0c830eabe9d2/go/src/pkg/os/exec
        exec.test 2220 gobuild  rtd    DIR  202,1     4096       2 /
        exec.test 2220 gobuild  txt    REG  202,1  4322404  167545 /tmp/go-build844875145/os/exec/_test/exec.test
        exec.test 2220 gobuild  mem    REG  202,1  1779492  394095 /lib/i386-linux-gnu/tls/i686/nosegneg/libc-2.17.so
        exec.test 2220 gobuild  mem    REG  202,1   125343  394109 /lib/i386-linux-gnu/tls/i686/nosegneg/libpthread-2.17.so
        exec.test 2220 gobuild  mem    REG  202,1   134376  393742 /lib/i386-linux-gnu/ld-2.17.so
        exec.test 2220 gobuild    0r   CHR    1,3      0t0    5576 /dev/null
        exec.test 2220 gobuild    1w  FIFO    0,8      0t0 5751814 pipe
        exec.test 2220 gobuild    2w  FIFO    0,8      0t0 5751814 pipe
        exec.test 2220 gobuild    3r   CHR    1,3      0t0    5576 /dev/null
        exec.test 2220 gobuild    4r  FIFO    0,8      0t0 5751900 pipe
        exec.test 2220 gobuild    5w  FIFO    0,8      0t0 5751900 pipe
        exec.test 2220 gobuild    6w   CHR    1,3      0t0    5576 /dev/null
        exec.test 2220 gobuild    7r  FIFO    0,8      0t0 5751901 pipe
        
        originally:
        COMMAND    PID    USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
        exec.test 2220 gobuild  cwd    DIR  202,1     4096  288319 /tmp/gobuilder/linux-386-387-0c830eabe9d2/go/src/pkg/os/exec
        exec.test 2220 gobuild  rtd    DIR  202,1     4096       2 /
        exec.test 2220 gobuild  txt    REG  202,1  4322404  167545 /tmp/go-build844875145/os/exec/_test/exec.test
        exec.test 2220 gobuild  mem    REG  202,1  1779492  394095 /lib/i386-linux-gnu/tls/i686/nosegneg/libc-2.17.so
        exec.test 2220 gobuild  mem    REG  202,1   125343  394109 /lib/i386-linux-gnu/tls/i686/nosegneg/libpthread-2.17.so
        exec.test 2220 gobuild  mem    REG  202,1   134376  393742 /lib/i386-linux-gnu/ld-2.17.so
        exec.test 2220 gobuild    0r   CHR    1,3      0t0    5576 /dev/null
        exec.test 2220 gobuild    1w  FIFO    0,8      0t0 5751814 pipe
        exec.test 2220 gobuild    2w  FIFO    0,8      0t0 5751814 pipe
        exec.test 2220 gobuild    4r  FIFO    0,8      0t0 5751857 pipe
FAIL



Why?

Why only this builder?

[ianlancetaylor]

Comment 1:

It looks like the extra pipes are two read pipes and one write pipe, which suggests that
they are the parent descriptors (reading from stdout and stderr, writing to stdin). 
Unfortunately that makes no sense at all since those are explicitly closed.

[bradfitz]

Comment 2:

I can reproduce this on that builder if anybody has theories for me to try.

[ianlancetaylor]

Comment 3:

Try changing os/pipe_linux.go to always use Pipe and CloseOnExec, rather than Pipe2.  As
far as I can tell that can not be the problem, but at the same time I can't see of any
other possibility.

[bradfitz]

Comment 4:

Nope, that doesn't fix it.
 
Also, I can reproduce on the same machine with GO386 unset (normal linux/386 mode).
Machine details, on EC2:
Linux gobuilder387 3.11.0-15-generic #25-Ubuntu SMP Thu Jan 30 17:25:07 UTC 2014 i686
i686 i686 GNU/Linux
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=13.10
DISTRIB_CODENAME=saucy
DISTRIB_DESCRIPTION="Ubuntu 13.10"
$ cat /proc/cpuinfo 
processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 23
model name  : Intel(R) Xeon(R) CPU           E5430  @ 2.66GHz
stepping    : 10
microcode   : 0xa07
cpu MHz     : 2659.994
cache size  : 6144 KB
fdiv_bug    : no
f00f_bug    : no
coma_bug    : no
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu tsc msr pae mce cx8 mca cmov pat pse36 clflush dts mmx fxsr sse sse2 ss ht
pbe nx lm constant_tsc arch_perfmon pebs bts pni dtes64 monitor ds_cpl vmx est tm2 ssse3
cx16 xtpr pdcm dca sse4_1 lahf_lm dtherm tpr_shadow vnmi flexpriority
bogomips    : 5319.98
clflush size    : 64
cache_alignment : 64
address sizes   : 38 bits physical, 48 bits virtual
power management:

[alberts]

Comment 5:

I've seen races before where we managed to find files and directories in /proc even
after system calls that would let you think that they should be gone have returned.
Could lsof be picking up just-closed file descriptors when reading /proc?

[bradfitz]

Comment 6:

Good theory.
I'm running now with GC disabled for that function (so no possibility of finalizers
closing the fds) and putting in a small sleep before the lsof check.
At 50 ms, I still saw a crash after a long run.
I'll collect some more numbers with different sleep intervals and see if a bigger sleep
causes a smaller percentage of failures.

[bradfitz]

Comment 7:

Seems like it's proc being slow.
I'll make the test more robust.

Owner changed to @bradfitz.

[bradfitz]

Comment 8:

For the record, I also tried disabling GC to rule out Go's finalizers closing fds. It
really does appear that Linux's /proc is only eventually consistent.
CL coming.

[gopherbot]

Comment 9:

CL https://golang.org/cl/90400044 mentions this issue.

[bradfitz]

Comment 10:

This issue was closed by revision 5600572.

Status changed to Fixed.