On Wed, Oct 24, 2012 at 4:30 PM, Ian Lance Taylor <i...@google.com> wrote:
> On Wed, Oct 24, 2012 at 6:19 AM, Uros Bizjak <ubiz...@gmail.com> wrote:
>> On Wed, Oct 24, 2012 at 3:10 PM, Ian Lance Taylor <i...@google.com> wrote:
>>> On Wed, Oct 24, 2012 at 5:31 AM, Uros Bizjak <ubiz...@gmail.com> wrote:
>>>> On Wed, Oct 24, 2012 at 2:18 PM, Andreas Schwab <sch...@linux-m68k.org>
>>>> wrote:
>>>>> Uros Bizjak <ubiz...@gmail.com> writes:
>>>>>
>>>>>> To answer my own question:
>>>>>>
>>>>>> dup(4) = 9
>>>>>> ...
>>>>>> close(9) = 0
>>>>>> dup(4) = -1 EBADF (Bad file descriptor)
>>>>>>
>>>>>> Test is calling dup on a closed file descriptor.
>>>>>
>>>>> FD 4 is most likely closed by one of the cloned threads. Use strace -f
>>>>> to follow them.
>>>>
>>>> Yes, indeed! Attached strace -f record confirms this on alpha.
>>>>
>>>> The same happens on x86_64, but for some reason x86_64 doesn't
>>>> complain when executing dup(2) on closed FD.
>>>
>>> The test execs itself by calling the fork and execve functions in
>>> libc. It is the child process that closes the FD after it forks.
>>> From the point of view of the parent process, the FD should still be
>>> open. I don't think you attached the strace -f output so I can't
>>> confirm this.
>>
>> Eh, sorry, attached now.
>>
>> After the second socketpair and before dup, there is a close in the same
>> thread.
>
> Thanks. I agree. Unfortunately, I can't figure out what is causing
> it. These seem to be the relevant calls.
>
> 16252 socketpair(PF_FILE, SOCK_STREAM, 0, [3, 4]) = 0
>
> 16252 clone(child_stack=0,
> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
> child_tidptr=0x20002f0ecd0) = 16259
>
> 16259 execve("./a.out", ["./a.out", "-test.run=^TestPassFD$", "--",
> "/tmp/TestPassFD684357043"], [/* 33 vars */] <unfinished ...>
>
> 16252 clone( <unfinished ...>
> 16252 <... clone resumed> child_stack=0x200031e2b70,
> flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
> parent_tidptr=0x200031e3350, tls=0x200031e3970,
> child_tidptr=0x200031e3350) = 16260
>
> ***** This is the bad call, but where does this come from?
> 16252 close(4 <unfinished ...>
> 16252 <... close resumed> ) = 0
>
> 16260 wait4(16259, <unfinished ...>
>
> 16261 read(9, <unfinished ...>
>
> 16259 sendmsg(5, {msg_name(0)=NULL, msg_iov(1)=[{"x", 1}],
> msg_controllen=24, {cmsg_len=20, cmsg_level=SOL_SOCKET,
> cmsg_type=SCM_RIGHTS, {9}}, msg_flags=0}, 0) = 1
>
> 16259 exit_group(0) = ?
>
> 16261 <... read resumed> "", 512) = 0
>
> 16260 <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0,
> {ru_utime={0, 46875}, ru_stime={0, 26367}, ...}) = 16259
>
> 16261 dup(4) = -1 EBADF (Bad file descriptor)
>
>
> Here is an approachj that might help. Set a breakpoint on socketpair.
> The failure comes after the second call to socketpair, the one from
> the function TestPassFD. After that breakpoint is reached, set a
> breakpoint on close. Look for the call to close(4). Get a backtrace
> from there so we can see what is calling it.
Continuing.
[New Thread 0x2000307b280 (LWP 8059)]
Breakpoint 18, 0x0000020002e378c0 in socketpair () from /lib/libc.so.6.1
Continuing.
[New Thread 0x20003083280 (LWP 8065)]
[Switching to Thread 0x20003083280 (LWP 8065)]
[...]
The first call with relevant FD is from:
Breakpoint 21, 0x0000020002e243f8 in close () from /lib/libc.so.6.1
(gdb) i r a0
a0 0x8 8
(gdb) bt
#0 0x0000020002e243f8 in close () from /lib/libc.so.6.1
#1 0x000000012003559c in syscall.Close (fd=<optimized out>) at libcalls.go:271
#2 0x00000200005d3cfc in os.close.pN7_os.file (file=0xf840414b70) at
../../../gcc-svn/trunk/libgo/go/os/file_unix.go:106
#3 0x0000020000888f18 in ffi_call_osf () at
../../../gcc-svn/trunk/libffi/src/alpha/osf.S:79
#4 0x00000200008889c4 in ffi_call (cif=<optimized out>, fn=<optimized
out>, rvalue=<optimized out>, avalue=0xf840c87fe8)
at ../../../gcc-svn/trunk/libffi/src/alpha/ffi.c:169
#5 0x0000020000558204 in reflect.call (func_type=0x200009e9650
<__go_td_FppN7_os.fileerN5_erroree>,
func_addr=0x200005d3c60 <os.close.pN7_os.file>,
is_interface=<optimized out>, is_method=<optimized out>,
params=0xf840c87fe0, results=0x0) at
../../../gcc-svn/trunk/libgo/runtime/go-reflect-call.c:498
#6 0x00000200005620b8 in runfinq (dummy=<optimized out>) at
../../../gcc-svn/trunk/libgo/runtime/mgc0.c:1168
#7 0x0000020000566b20 in kickoff () at
../../../gcc-svn/trunk/libgo/runtime/proc.c:338
#8 0x0000020002d8d024 in ?? () from /lib/libc.so.6.1
[... dup call follows from the same thread ...]
Breakpoint 22, 0x0000020002e24e90 in dup () from /lib/libc.so.6.1
(gdb) i r a0
a0 0x8 8
(gdb) bt
#0 0x0000020002e24e90 in dup () from /lib/libc.so.6.1
#1 0x000000012003578c in syscall.Dup (oldfd=8) at libcalls.go:314
#2 0x00000200005b2794 in net.newFileFD (f=0xf8400004a0) at
../../../gcc-svn/trunk/libgo/go/net/file_unix.go:16
#3 0x00000200005c0dcc in net.FileConn (f=0x8) at
../../../gcc-svn/trunk/libgo/go/net/file_unix.go:78
#4 0x00000001200433e4 in syscall_test.TestPassFD (t.param=<optimized
out>) at passfd_test.go:60
#5 0x0000020000623920 in testing.tRunner (test=0xf840414978,
t.param=<optimized out>)
at ../../../gcc-svn/trunk/libgo/go/testing/testing.go:301
#6 testing.$thunk7 (__go_thunk_parameter=<optimized out>) at
../../../gcc-svn/trunk/libgo/go/testing/testing.go:377
#7 0x0000020000566b20 in kickoff () at
../../../gcc-svn/trunk/libgo/runtime/proc.c:338
#8 0x0000020002d8d024 in ?? () from /lib/libc.so.6.1
Uros.
