Messages in this thread | | | Subject | Re: [RFC PATCH] set TASK_TRACED before arch_ptrace code to fix a race | From | Petr Tesarik <> | Date | Thu, 05 Jun 2008 13:16:45 +0200 |
| |
On Thu, 2008-06-05 at 09:49 +0800, Luming Yu wrote: > On Wed, Jun 4, 2008 at 5:16 PM, Petr Tesarik <ptesarik@suse.cz> wrote: > > Luming Yu wrote: > >>> It's definitely a bug in strace. For some reason (I don't care about) > >>> the execve() syscall produces an extra notification. However, this > >>> notification message is suppressed when SIGTRAP is blocked. This > >>> explains why the test case fails only when SIGTRAP is blocked. > >> > >> This is exact problem I suspected and I was trying to address in my hack.. > >> Since there are several processes involved in the pretty complex > >> ptrace scenario., > >> I need to capture all processes context with kdump to confirm this is > >> exact root-cause > >> for the problem. But kdump doesn't work for me..I'm trying to solve it now.. > >> > >> I'm also in doubt about the semantic correctness of the test case.. > >> Since SIGTRAP is so necessary to get ptrace work, is it legitimate to > >> block it in test case? > >> > >> One more thing I need to say is: > >> Same strace works for utrace enabled kernel on IA64.. If the bug is in > >> strace, how could it happen? > > > > No idea, but send me the strace.log file from running > > > > strace -o strace.log strace -f -o log.txt ./test1 > > > > and I may be able to tell. > > Please check the attachment! > > > > > Petr Tesarik > >
Hm, I think without utrace, it gets out-of-sync once, so syscall entries and exits are swapped from that point on. With utrace, it gets out-of-sync _twice_, so it eventually looks fine. But the strace output definitely looks incorrect even with utrace:
5718 execve("./test2.sh", [], [/* 23 vars */]) = 1 5718 execve("", [0x840c001000100003, 0x26230c14203032, 0x8cb0008800140a81, 0xa643100801808402, 0x2400905000040088, 0x11600a0072000001, 0xad814a00402e0, 0x2200012464009344, 0x1180418512c40026, 0x400003081880008, 0x2100010840910404, 0x8045120000800003, 0x6400000c0000600, 0xc20063440501400, 0x1048015002008081, 0xe02226005008c010, ...], [/* 0 vars */]) = 1 5718 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
Note that strace missed a brk() syscall, although I can actually see this in the other trace you sent me:
wait4(-1, [{WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP}], __WALL, NULL) = 5704 ptrace(PTRACE_PEEKUSER, 5704, psr, NULL) = 4398046511120 ptrace(PTRACE_PEEKUSER, 5704, r15, NULL) = 1060 ptrace(PTRACE_SYSCALL, 5704, 0x1, SIG_0) = 0
Look at the value of r15, and compare it with unistd.h: #define __NR_brk 1060
I _guess_ this is caused by the fact that test2.sh is a shell script, so the kernel executes the shell, and maybe utrace produces a second execve notifications in this case? Roland, can you shed some light?
Petr Tesarik
| |