Issue 29 in fabricate: Traceback when seeing new process syscall (vfork processed ? )

[fabr...@googlecode.com]

Status: New
Owner: ----
Labels: Type-Defect Priority-Medium

New issue 29 by mathieu....@gmail.com: Traceback when seeing new process
syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Hello,

I get the following traceback on a quite simple fabric file.
Strangely enough, on the corresponding strace file, I get an "open" line
before the "execve" one…


Traceback (most recent call last):
File "./fabric.py", line 22, in <module>
main()

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 1402, in main
this_status = eval(action, globals_dict)
File "<string>", line 1, in <module>
File "./fabric.py", line 8, in build
gen_source(1, s)
File "./fabric.py", line 17, in gen_source
run(VALIDSH, str(chain), '--gen', scenario)

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 1233, in run
return default_builder.run(*args, **kwargs)

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 998, in run
deps, outputs = self.runner(*arglist, **kwargs)

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 689, in __call__
return self._runner(*args, **kwargs)

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 644, in __call__
status, deps, outputs = self._do_strace(args, kwargs, outfile, outname)

File "/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/fabricate.py",
line 585, in _do_strace
cwd = processes[pid].cwd
KeyError: '15151'

Here is the relevant portion of the strace file (with first lines where
15151 pid appears)

15138 vfork( <unfinished ...>
15151 open("/proc/self/fd", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
15151
execve("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/bin/bpp.sh",
["bpp.sh", "/home/clabaut/c478/c478_traducte"..., "/tmp/File2606627264771462039.tmp"],
[/* 67 vars */]) = -1 ENOENT (No such file or directory)
15151
execve("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/runtime/bpp/bpp.sh",
["bpp.sh", "/home/clabaut/c478/c478_traducte"..., "/tmp/File2606627264771462039.tmp"],
[/* 67 vars */]) = -1 ENOEXEC (Exec format error)
15151 execve("/bin/sh",
["/bin/sh", "/home/clabaut/c478/c478_traducte"..., "/home/clabaut/c478/c478_traducte"..., "/tmp/File2606627264771462039.tmp"],
[/* 67 vars */] <unfinished ...>
15138 <... vfork resumed> ) = 15151
15151 <... execve resumed> ) = 0
15151 open("/etc/ld.so.cache", O_RDONLY) = 3
15151 open("/lib/libreadline.so.6", O_RDONLY) = 3
15151 open("/lib/libncursesw.so.5", O_RDONLY) = 3
15151 open("/lib/libdl.so.2", O_RDONLY) = 3
15151 open("/lib/libc.so.6", O_RDONLY) = 3
15138 clone(child_stack=0x7f10de33aff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|
CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|
CLONE_CHILD_CLEARTID, parent_tidptr=0x7f10de33b9d0, tls=0x7f10de33b700,
child_tidptr=0x7f10de33b9d0) = 15152
15151 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
15151 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
15151 open("/proc/meminfo", O_RDONLY) = 3
15151 open("/usr/lib/gconv/gconv-modules.cache", O_RDONLY) = -1 ENOENT (No
such file or directory)
15151 open("/usr/lib/gconv/gconv-modules", O_RDONLY) = 3
15151
open("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/runtime/bpp/bpp.sh",
O_RDONLY) = 3
15151 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f8d2392c9d0) = 15153
15153 execve("/bin/uname", ["uname", "-s"], [/* 66 vars */]) = 0
15153 open("/etc/ld.so.cache", O_RDONLY) = 3
15153 open("/lib/libc.so.6", O_RDONLY) = 3
15153 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
15153 exit_group(0) = ?
15151 --- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=15153, si_status=0,
si_utime=0, si_stime=0} (Child exited) ---
15151 open("/tmp/ttt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
15151 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f8d2392c9d0) = 15155
15151 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f8d2392c9d0) = 15156
15151 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f8d2392c9d0) = 15157
15156 execve("/lib/cpp",
["/lib/cpp", "-traditional", "-P", "-C", "-undef"], [/* 66 vars */]) = 0
15156 open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
15155
execve("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/runtime/bpp/bpp",
["bpp", "/home/clabaut/c478/c478_traducte"...], [/* 66 vars */]
<unfinished ...>
15156 <... open resumed> ) = 3
15156 open("/lib/libc.so.6", O_RDONLY) = 3
15155 <... execve resumed> ) = 0
15155 open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
15157 open("/tmp/File2606627264771462039.tmp", O_WRONLY|O_CREAT|O_TRUNC,
0666) = 3
) = 0
15157 execve("/bin/sed",
["sed", "-e", "s,\\\\#,#,g", "-e", "s,\\\\\\\\,\\\\,g"], [/* 66 vars */]
<unfinished ...>
15155 open("/lib32/libc.so.6", O_RDONLY) = 3
15156 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
15157 <... execve resumed> ) = 0
15156 open("/usr/share/locale/locale.alias", O_RDONLY) = 3
15157 open("/etc/ld.so.cache", O_RDONLY) = 3
) = 0
15157 open("/lib/libacl.so.1", O_RDONLY) = 3
15156 open("/usr/share/locale/fr_FR.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
15156 open("/usr/share/locale/fr_FR/LC_MESSAGES/gcc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
15156 open("/usr/share/locale/fr.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
15156 open("/usr/share/locale/fr/LC_MESSAGES/gcc.mo", O_RDONLY) = 3
15157 open("/lib/libc.so.6", O_RDONLY) = 3
15155
open("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/RT7_2/in/m1_i.imp",
O_RDONLY <unfinished ...>
15157 open("/lib/libattr.so.1", O_RDONLY) = 3
15155 exit_group(0) = ?
15157 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
15157 open("/usr/lib/charset.alias", O_RDONLY) = -1 ENOENT (No such file or
directory)
15157 open("/usr/lib/gconv/gconv-modules.cache", O_RDONLY) = -1 ENOENT (No
such file or directory)
15157 open("/usr/lib/gconv/gconv-modules", O_RDONLY) = 3
15156 vfork( <unfinished ...>
15161 execve("/usr/lib/gcc/x86_64-unknown-linux-gnu/4.6.2/cc1",
["/usr/lib/gcc/x86_64-unknown-linu"..., "-E", "-traditional-cpp", "-quiet", "-C", "-P", "-", "-mtune=generic", "-march=x86-64", "-undef"],
[/* 69 vars */] <unfinished ...>
15156 <... vfork resumed> ) = 15161
15161 <... execve resumed> ) = 0
15161 open("/etc/ld.so.cache", O_RDONLY) = 3
15161 open("/usr/lib/libcloog-isl.so.2", O_RDONLY) = 3
15161 open("/usr/lib/libisl.so.7", O_RDONLY) = 3
15161 open("/usr/lib/libppl_c.so.4", O_RDONLY) = 3
15161 open("/usr/lib/libppl.so.9", O_RDONLY) = 3
15161 open("/usr/lib/libpwl.so.5", O_RDONLY) = 3
15161 open("/usr/lib/libgmpxx.so.4", O_RDONLY) = 3
15161 open("/usr/lib/libmpc.so.2", O_RDONLY) = 3
15161 open("/usr/lib/libmpfr.so.4", O_RDONLY) = 3
15161 open("/usr/lib/libgmp.so.10", O_RDONLY) = 3
15161 open("/lib/libdl.so.2", O_RDONLY) = 3
15161 open("/usr/lib/libz.so.1", O_RDONLY) = 3
15161 open("/lib/libc.so.6", O_RDONLY) = 3
15161 open("/usr/lib/libstdc++.so.6", O_RDONLY) = 3
15161 open("/lib/libm.so.6", O_RDONLY) = 3
15161 open("/usr/lib/libgcc_s.so.1", O_RDONLY) = 3
15161 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
15161 open("/usr/share/locale/locale.alias", O_RDONLY) = 3
15161 open("/usr/share/locale/fr_FR.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
15161 open("/usr/share/locale/fr_FR/LC_MESSAGES/gcc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
15161 open("/usr/share/locale/fr.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
15161 open("/usr/share/locale/fr/LC_MESSAGES/gcc.mo", O_RDONLY) = 3
15161 open("/proc/meminfo", O_RDONLY) = 3
15161 open("/proc/meminfo", O_RDONLY) = 3
15161 open("/proc/meminfo", O_RDONLY) = 3
15161 open("/usr/lib/gconv/gconv-modules.cache", O_RDONLY) = -1 ENOENT (No
such file or directory)
15161 open("/usr/lib/gconv/gconv-modules", O_RDONLY) = 3
15161 open("/usr/lib/gconv/ISO8859-1.so", O_RDONLY) = 3
15161 exit_group(0) = ?
15156 --- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=15161, si_status=0,
si_utime=0, si_stime=0} (Child exited) ---
15156 exit_group(0) = ?
15157 exit_group(0) = ?
15151 --- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=15155, si_status=0,
si_utime=0, si_stime=0} (Child exited) ---
15151 exit_group(0) = ?
15152 --- {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=15151, si_status=0,
si_utime=0, si_stime=0} (Child exited) ---

[fabr...@googlecode.com]

Comment #1 on issue 29 by benh...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Thanks for the report, Mathieu. Does this happen every time? Could you
please post your fabricate build file? (Or even better, a small,
stand-alone build file that reproduces this problem?)

[fabr...@googlecode.com]

Comment #2 on issue 29 by ele...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

As noted by the OP the problem is that the vfork() which creates process
15151 is interrupted by an open() running as 15151 but since the vfork was
interrupted the entry in the process dict has not been created.

ATM fabricate only creates processes on completion of fork/clone or exec
but POSIX allows some syscalls between the fork and the exec which run as
the new pid.

The solution would be to look at the pid before anything else and create
the process dict entry irrespective of the call type, or more correctly but
complicated is to defer processing of interrupting calls until the
interrupted one is finished.

[fabr...@googlecode.com]

Comment #3 on issue 29 by mathieu....@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

I guess that creating the dict entry irrespective of the call type will do
the trick…
I'll give a try

[fabr...@googlecode.com]

Comment #4 on issue 29 by benh...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Did doing that solve the problem, Mathieu? I haven't had a chance to play
with this yet (I don't run Linux myself). Can we repro this with a small C
program that uses fork and open, which fabricate would run?

[fabr...@googlecode.com]

Comment #5 on issue 29 by mathieu....@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

It seems to solve the problem (I'll try to set up a test case as soon I
have some spare time), but I stumbled into another one, where I have the
two consecutive line in the strace output :

28033 <... fork resumed> ) = 3
28033 <... open resumed> ) = 0

Leading to a key error at line "line = unfinished[pid] + body"

It is very strange as I have only one "unfinished" line for process 28033,
which is an "open" one (no "fork" one) !


In another attempt, where I ignore "fork resumed" lines, I get a strace
with only one "open unfinished" line for process 32491 but got *two*
subsequent "open resumed" for this same process !
I was trying to improve unfinished treatment, but now I do not understand
what is the meaning of such strace ouptut…

[fabr...@googlecode.com]

Comment #6 on issue 29 by ele...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Hi Mathieu,

Could you post with the whole relevant section of the strace.

Thanks
Lex

[fabr...@googlecode.com]

Comment #7 on issue 29 by mathieu....@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Of course.
Here are two samples of two consecutive runs :

24250 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f3da39a09d0) = 24253
24250 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f3da39a09d0) = 24254
24253 execve("/lib/cpp",
["/lib/cpp", "-traditional", "-P", "-C", "-undef"], [/* 69 vars */]) = 0
24253 open("/etc/ld.so.cache", O_RDONLY) = 3
24253 open("/lib/libc.so.6", O_RDONLY) = 3
24254 open("/tmp/File73712902416211553.tmp", O_WRONLY|O_CREAT|O_TRUNC,
0666) = 3
24252
execve("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/runtime/bpp/bpp",
["bpp", "/home/clabaut/c478/c478_traducte"...], [/* 69 vars */]
<unfinished ...>
24254 execve("/bin/sed",
["sed", "-e", "s,\\\\#,#,g", "-e", "s,\\\\\\\\,\\\\,g"], [/* 69 vars */]) =
0
24252 <... execve resumed> ) = 0
24252 open("/etc/ld.so.cache", O_RDONLY) = 3
24254 open("/etc/ld.so.cache", O_RDONLY) = 3
) = 31768576
24254 open("/lib/libacl.so.1", O_RDONLY <unfinished ...>
24253 open("/usr/lib/locale/locale-archive", O_RDONLY <unfinished ...>
24254 <... open resumed> ) = 3
24253 <... open resumed> ) = 3
24252 open("/lib32/libc.so.6", O_RDONLY <unfinished ...>
24253 <... open resumed> ) = 0

And
23684 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0x7f795a5e69d0) = 23688
23687 execve("/lib/cpp",
["/lib/cpp", "-traditional", "-P", "-C", "-undef"], [/* 69 vars */]) = 0
23687 open("/etc/ld.so.cache", O_RDONLY) = 3
23687 open("/lib/libc.so.6", O_RDONLY) = 3
23686
execve("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/runtime/bpp/bpp",
["bpp", "/home/clabaut/c478/c478_traducte"...], [/* 69 vars */]
<unfinished ...>
23688 open("/tmp/File7942459553864738579.tmp", O_WRONLY|O_CREAT|O_TRUNC,
0666) = 3
23688 execve("/bin/sed",
["sed", "-e", "s,\\\\#,#,g", "-e", "s,\\\\\\\\,\\\\,g"], [/* 69 vars */]
<unfinished ...>
23686 <... execve resumed> ) = 0
23688 <... execve resumed> ) = 0
23687 open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
) = 0
23688 open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
23686 open("/etc/ld.so.cache", O_RDONLY <unfinished ...>
23688 <... fork resumed> ) = 3
23686 <... open resumed> ) = 3
23688 open("/lib/libacl.so.1", O_RDONLY <unfinished ...>
23687 open("/usr/share/locale/locale.alias", O_RDONLY <unfinished ...>
23688 <... open resumed> ) = 3
23687 <... open resumed> ) = 3
23686 open("/lib32/libc.so.6", O_RDONLY <unfinished ...>
23688 <... open resumed> ) = 0
23688 open("/lib/libc.so.6", O_RDONLY) = 3
23687 open("/usr/share/locale/fr_FR.UTF-8/LC_MESSAGES/gcc.mo", O_RDONLY) =

-1 ENOENT (No such file or directory)

23687 open("/usr/share/locale/fr_FR.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) =

-1 ENOENT (No such file or directory)

23687 open("/usr/share/locale/fr_FR/LC_MESSAGES/gcc.mo", O_RDONLY) = -1

ENOENT (No such file or directory)

23687 open("/usr/share/locale/fr.UTF-8/LC_MESSAGES/gcc.mo", O_RDONLY) = -1

ENOENT (No such file or directory)

23687 open("/usr/share/locale/fr.utf8/LC_MESSAGES/gcc.mo", O_RDONLY) = -1

ENOENT (No such file or directory)

23688 open("/lib/libattr.so.1", O_RDONLY <unfinished ...>
23687 open("/usr/share/locale/fr/LC_MESSAGES/gcc.mo", O_RDONLY) = 3
23688 <... fork resumed> ) = 3
23688 <... open resumed> ) = 0
23686
open("/home/clabaut/c478/c478_traducteur_java_hgsvn/traducteurBversCJavaTest/validation/tests/TC3/in/m_typ.mch",
O_RDONLY <unfinished ...>
23688 <... execve resumed> ) = 0


In the first one, there is only one "open…unfinished" for
two "open…resumed"…

[Lex Trotman]

Mathieu,

Which platform are you running on?

[fabr...@googlecode.com]

Comment #8 on issue 29 by ele...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Hi Mathieu,

Somehow a reply where I requested what operating systen, version and strace
version you were using did not get attached to the issue.

[fabr...@googlecode.com]

Comment #9 on issue 29 by mathieu....@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Hi Lex,
My operating system is :
Linux 3.1.9-2-ARCH #1 SMP PREEMPT Sat Jan 14 09:11:37 CET 2012 x86_64
Intel(R) Core(TM) i5-2520M CPU @ 2.50GHz GenuineIntel GNU/Linux

strace version is : 4.6

Best regards,
-Mathieu

[fabr...@googlecode.com]

Comment #10 on issue 29 by ele...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Thanks Mathieu,

It apears to be a problem with strace, if you are happy for me to submit
the two strace fragments to that project please provide them as an
attachment so we know that the comment and mail system hasn't wrapped or
otherwise modified them. (there are some strange artifacts that suggest
they have been modified in transit).

Cheers
Lex

[fabr...@googlecode.com]

Comment #11 on issue 29 by ele...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Mathieu,

As a postscript, if you can back your strace version to 4.5 and confirm the
problem does not occur (I'm on 4.5.20 and havn't seen any problems) that is
important information for the strace folks.

Cheers
Lex

[fabr...@googlecode.com]

Updates:
Status: Started

Comment #12 on issue 29 by simon.al...@gmail.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

I am starting work on fixing this issue. The suggested fix of just creating
the process dict entry obviously works for mathieu, but it does lose some
of the functionality of a proper clone_match in the StraceRunner. That
being to transfer the cwd to the new process dict entry.

I also noticed that the execve_match basically does the suggested fix of
just creating the process dict entry if it does not exist. This is also
missing the transfer of the cwd to the new process dict entry. I am
surprised this has not caused any issues. My assumption is that the
original reason for this was to pick up the initial execve that kicks off
the very first process traced, not to fix the interrupted fork.

I think the correct fix is to delay any matching until the clone has
completed. I think this should be simple enough to do. Just create the
StraceProcess object for the pid if it does not exist, but mark is as "not
fully cloned". Any lines that match before the clone completes can be
cached in the process entry. When the clone completes the lines can be
re-processed and correct deps extracted. For execve there will have to be a
special case to create a process dict entry if there are no processes being
tracked. Does any one see any problems with this approach?



--
You received this message because this project is configured to send all
issue notifications to this address.
You may adjust your notification preferences at:
https://code.google.com/hosting/settings

[fabr...@googlecode.com]

Comment #13 on issue 29 by wer...@beroux.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Seeing this issue during django-manage makemessages (basically gettext).

[fabr...@googlecode.com]

Comment #14 on issue 29 by wer...@beroux.com: Traceback when seeing new

process syscall (vfork processed ? )
http://code.google.com/p/fabricate/issues/detail?id=29

Are you still working on this from time to time?