[Bug runtime/14659] New: task_finder2 breaks ptrace apps

[Bug runtime/14659] New: task_finder2 breaks ptrace apps

[jistone at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

             Bug #: 14659
           Summary: task_finder2 breaks ptrace apps
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap@sourceware.org
        ReportedBy: jistone@redhat.com
    Classification: Unclassified


I'm running on kernel 3.5.4-1.fc17.x86_64, which is utrace-free, thus using
task_finder2.  I was trying to debug a problem between stapdyn and its module,
but when certain kernel-mode stap scripts are running, dyninst is completely
disrupted.  I can reproduce this with strace too, so I think it's a conflict
with ptrace().

First the good output, then the bad stap runs:

> $ strace -e read true
> read(4, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\30B\273?\0\0\0"..., 832) = 832
> +++ exited with 0 +++


> $ stap -V
> Systemtap translator/driver (version 2.0/0.154, commit release-1.8-311-g44f25c1)
> Copyright (C) 2005-2012 Red Hat, Inc. and others
> This is free software; see the source for copying conditions.
> enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS DYNINST

> $ stap -e 'probe never{print_ubacktrace()}' -c 'strace -e read true'
> --- SIGTRAP {si_signo=SIGTRAP, si_code=0x5, si_pid=9294, si_uid=10719} ---
> --- SIGTRAP {si_signo=SIGTRAP, si_code=SI_KERNEL} ---
> +++ killed by SIGTRAP +++
> Warning: child process exited with signal 5 (Trace/breakpoint trap)
> WARNING: /usr/local/bin/staprun exited with status: 1
> Pass 5: run failed.  Try again with another '--vp 00001' option.

> $ stap -e 'probe process.begin{next}' -c 'strace -e read true'
> +++ exited with 0 +++

The same tests work fine on 2.6.32-279.5.2.el6.x86_64, with utrace, which is
why I blamed task_finder2 in the subject.  It could also be a bug in any of the
new kernel infrastructure that task_finder2 uses though.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

David Smith <dsmith at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dsmith at redhat dot com

--- Comment #1 from David Smith <dsmith at redhat dot com> 2012-10-08 19:06:29 UTC ---
I've been looking at this one.  At first I thought it might be related to
runtime/stp_utrace.c's use of the TASK_TRACED flag, but even without that, the
example in this testcase still failed.

Here's what the testcase breaks down to:

====
# stap -vp2 -e 'probe never{print_ubacktrace()}' -c 'strace -e read true'
Pass 1: parsed user script and 89 library script(s) using
202528virt/22076res/2772shr/19600data kb, in 180usr/50sys/237real ms.
# functions
print_ubacktrace:unknown ()
%{ /* pragma:unwind */ /* pragma:symbols */
/* myproc-unprivileged */ /* pragma:uprobes */ /* pragma:vma */
    _stp_stack_user_print(CONTEXT, _STP_SYM_FULL);
%}
# probes
never /* <- never */
print_ubacktrace()
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 embed(s), 0 global(s)
using 203060virt/22848res/3040shr/20132data kb, in 0usr/0sys/12real ms.
+===

So, the print_ubacktrace() function uses several pragmas.  I've narrowed things
down to the following script which gets the same error:

====
# functions
function doit()
%{ /* pragma:vma */

    _stp_print("never\n");
%}

# probes
probe never {
      doit()
}
====

The vma pragma turns on vma tracking in task_finder2, which turns on syscall
tracing. I'll bet that is what is interfering with ptrace().

When doing syscall tracing, task_finder2 attaches to the 'sys_enter' and
'sys_exit' tracepoints. Setting a handler on those tracepoints sets the
TIF_SYSCALL_TRACEPOINT task flag, which gets checked along with the
TIF_SYSCALL_TRACE task flag (which ptrace uses) in _TIF_WORK_SYSCALL_MASK.

Here's a syscall tracing test that shows similar behavior:

====
# stap -v -e 'probe process.syscall{printf("%d\n", $syscall)}' -c 'strace -e
read true'
Pass 1: parsed user script and 89 library script(s) using
204748virt/22196res/2856shr/19720data kb, in 170usr/50sys/232real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 1 embed(s), 0 global(s)
using 205276virt/22968res/3128shr/20248data kb, in 0usr/0sys/6real ms.
Pass 3: translated to C into
"/tmp/stappzFQd4/stap_31c0780e9dc65829f8476ec5a54fb52b_1254_src.c" using
205276virt/23300res/3432shr/20248data kb, in 0usr/0sys/1real ms.
Pass 4: compiled C into "stap_31c0780e9dc65829f8476ec5a54fb52b_1254.ko" in
2940usr/1620sys/5112real ms.
Pass 5: starting run.
--- SIGTRAP {si_signo=SIGTRAP, si_code=0x5, si_pid=12793, si_uid=5183} ---
--- SIGTRAP {si_signo=SIGTRAP, si_code=SI_KERNEL} ---
+++ killed by SIGTRAP (core dumped) +++
Warning: child process exited with signal 5 (Trace/breakpoint trap)
15
13
14
59
59
59
59
12
9
21
2
5
9
3
2
0
5
9
10
9
9
3
9
9
158
10
10
10
11
13
39
63
12
12
12
102
104
56
61
101
101
61
101
61
62
101
61
101
101
61
101
61
231
4
4
4
4
4
56
13
13
13
13
13
13
13
14
14
14
61
101
14
101
101
1
101
14
61
14
101
1
101
14
61
14
1
160
13
234
WARNING: /usr/local/bin/staprun exited with status: 1
Pass 5: run completed in 20usr/220sys/703real ms.
Pass 5: run failed.  Try again with another '--vp 00001' option.
====

I'll think about ways to avoid syscall tracing when doing vma tracking.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[jistone at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

--- Comment #2 from Josh Stone <jistone at redhat dot com> 2012-10-08 19:26:18 UTC ---
(In reply to comment #1)
> The vma pragma turns on vma tracking in task_finder2, which turns on syscall
> tracing. I'll bet that is what is interfering with ptrace().
> 
> When doing syscall tracing, task_finder2 attaches to the 'sys_enter' and
> 'sys_exit' tracepoints. Setting a handler on those tracepoints sets the
> TIF_SYSCALL_TRACEPOINT task flag, which gets checked along with the
> TIF_SYSCALL_TRACE task flag (which ptrace uses) in _TIF_WORK_SYSCALL_MASK.

I'm skeptical of this root cause, because syscall tracepoints don't cause any
problem with perf:

$ perf record -e raw_syscalls:sys_* strace -e read true
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\30\242b<\0\0\0"...,
832) = 832
+++ exited with 0 +++
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.088 MB perf.data (~3830 samples) ]

Actually, even stap is fine on the raw tracepoints:

$ stap eventcount.stp 'kernel.trace("sys_enter")' \
    'kernel.trace("sys_exit")' -c 'strace -e read true'
read(4, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\30\242b<\0\0\0"...,
832) = 832
+++ exited with 0 +++
Starting event counting at Mon Oct  8 12:24:46 2012 PDT, pid 27963 + children
Finished event counting at Mon Oct  8 12:24:47 2012 PDT.
Total time elapsed: 34 ms, 760 events total, 686 after filtering.
TID                       EVENT                          COUNT (RATE Hz)
---                       -----                          ---------------
stapio(27963)             kernel.trace("sys_enter")      7 (205.88)
stapio(27963)             kernel.trace("sys_exit")       7 (205.88)
strace(27963)             kernel.trace("sys_enter")      305 (8970.58)
strace(27963)             kernel.trace("sys_exit")       305 (8970.58)
strace(27966)             kernel.trace("sys_exit")       3 (88.23)
strace(27966)             kernel.trace("sys_enter")      3 (88.23)
strace(27967)             kernel.trace("sys_exit")       5 (147.05)
strace(27967)             kernel.trace("sys_enter")      5 (147.05)
true(27967)               kernel.trace("sys_exit")       23 (676.47)
true(27967)               kernel.trace("sys_enter")      23 (676.47)

> I'll think about ways to avoid syscall tracing when doing vma tracking.

If there's really a problem between the kernel's syscall tracing and ptrace,
then we should report this as a kernel bug.  But right now, it seems like
there's more going on...

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

--- Comment #3 from David Smith <dsmith at redhat dot com> 2012-10-08 20:42:33 UTC ---
(In reply to comment #2)
> If there's really a problem between the kernel's syscall tracing and ptrace,
> then we should report this as a kernel bug.  But right now, it seems like
> there's more going on...

Looks like you are right that it isn't syscall probing directly.

Looking back at the test script I posted earlier:

====
# functions
function doit()
%{ /* pragma:vma */

    _stp_print("never\n");
%}

# probes
probe never {
      doit()
}
====

That script causes the bad SIGTRAP behavior.  However, if I stub out
_stp_vma_init() and _stp_vma_done() I don't see the SIGTRAPs.

So, it isn't the syscall tracing in the vma tracking stuff, but it is something
else that the vma tracking does.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

--- Comment #4 from David Smith <dsmith at redhat dot com> 2012-10-08 21:02:41 UTC ---
(In reply to comment #3)
> (In reply to comment #2)
> > If there's really a problem between the kernel's syscall tracing and ptrace,
> > then we should report this as a kernel bug.  But right now, it seems like
> > there's more going on...
> 
> Looks like you are right that it isn't syscall probing directly.
> 
> Looking back at the test script I posted earlier:
> 
> ====
> # functions
> function doit()
> %{ /* pragma:vma */
> 
>     _stp_print("never\n");
> %}
> 
> # probes
> probe never {
>       doit()
> }
> ====
> 
> That script causes the bad SIGTRAP behavior.  However, if I stub out
> _stp_vma_init() and _stp_vma_done() I don't see the SIGTRAPs.
> 
> So, it isn't the syscall tracing in the vma tracking stuff, but it is something
> else that the vma tracking does.

After poking this a bit more, it could be that stubbing out _stp_vma_init()
also removes the only task_finder client, so it doesn't do anything.

I get the following output with a simple process.begin probe:

===
stap -e 'probe process.begin { printf("%s\n", execname()) }' -c 'strace -e read
true'
+++ exited with 0 +++
stapio
strace
strace
strace
true
===

Here we don't get the SIGTRAP, but we don't get strace's output either.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[dsmith at redhat dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

David Smith <dsmith at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |FIXED

--- Comment #5 from David Smith <dsmith at redhat dot com> 2012-10-11 15:58:04 UTC ---
Commit c551686 fixes this problem (and adds a testcase).

Oleg Nesterov figured out that stp_utrace.c was using TIF_SYSCALL_TRACE when it
shouldn't.

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.

[Bug runtime/14659] task_finder2 breaks ptrace apps

[agentzh at gmail dot com]

http://sourceware.org/bugzilla/show_bug.cgi?id=14659

agentzh <agentzh at gmail dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |agentzh at gmail dot com

--- Comment #6 from agentzh <agentzh at gmail dot com> 2012-10-11 22:29:58 UTC ---
*** Bug 14537 has been marked as a duplicate of this bug. ***

-- 
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.