Re: uprobes: bug in comm/string output?

[Masami Hiramatsu <mhiramat@kernel.org>]

On Tue, 15 Jan 2019 14:36:48 +0100
Andreas Ziegler <andreas.ziegler@fau.de> wrote:

> Hi again,
> 
> On 1/14/19 1:38 PM, Andreas Ziegler wrote:
> > Hi,
> > 
> > I've been playing around with uprobes today and found the following weird behaviour/output when using more than one string argument (or using the $comm argument). This was run on a v4.20 mainline build on Ubuntu 18.04.
> > 
> > root@ubuntu1810:~# uname -a
> > Linux ubuntu1810 4.20.0-042000-generic #201812232030 SMP Mon Dec 24 01:32:58 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
> > 
> > I'm trying to track calls to dlopen so I'm looking up the correct offset in libdl.so:
> > 
> > root@ubuntu1810:/sys/kernel/debug/tracing# readelf -s /lib/x86_64-linux-gnu/libdl-2.28.so | grep dlopen
> >     34: 00000000000012a0   133 FUNC    GLOBAL DEFAULT   14 dlopen@@GLIBC_2.2.5
> > 
> > Then I'm creating a uprobe with two prints of $comm and two prints of the first argument to dlopen, and enable that probe. The '/root/test' program only does a dlopen("libc.so.6", RTLD_LAZY) in main().
> > 
> > root@ubuntu1810:/sys/kernel/debug/tracing# echo 'p:dlopen /lib/x86_64-linux-gnu/libdl-2.28.so:0x12a0 $comm $comm +0(%di):string +0(%di):string' > uprobe_events
> > root@ubuntu1810:/sys/kernel/debug/tracing# echo 1 > events/uprobes/dlopen/enable
> > root@ubuntu1810:/sys/kernel/debug/tracing# /root/test
> > 
> > The trace output looks like this:
> > 
> > root@ubuntu1810:/sys/kernel/debug/tracing# cat trace
> > # tracer: nop
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >             test-1617  [000] d...  1237.959168: dlopen: (0x7fbd5272e2a0) arg1=(fault) arg2=(fault) arg3="libc.so.6libc.so.6" arg4="libc.so.6" 
> > 
> > That's very weird for two reasons:
> > - fetching $comm seems to fail with an invalid pointer
> > - arg3 contains the text twice (if I add another print of the argument, arg3 will contain the wanted string three times, arg4 two times and the last argument will contain it once). 
> 
> at least for the second problem I think I found the answer, and for the 
> first problem I have a suspicion (see last paragraph for that).

OK, this looks broken. Thank you very much for reporting it!

BTW, I tried to reproduce it with kprobe event, but it seems working well. e.g.

 # echo 'p ksys_chdir $comm $comm +0(%di):string +0(%di):string' > kprobe_events 
 # echo 1 > events/kprobes/enable
 # cd /sys/kernel/debug/tracing
 # cat trace
              sh-812   [003] ...1   229.344360: p_ksys_chdir_0: (ksys_chdir+0x0/0xc0) arg1="sh" arg2="sh" arg3="/sys/kernel/debug/tracing" arg4="/sys/kernel/debug/tracing"

So, it might be an issue on uprobe_event.

> 
> For this, I installed a uprobe for libdl.so/dlopen once again, the 
> command would be
> 
> 'p:dlopen /lib/x86_64-linux-gnu/libdl-2.28.so:0x12a0 $comm $comm'
> 
> so it should print the process name twice (using a kernel v4.18 on 
> Ubuntu 18.10).
> 
> The code which prints the collected data (print_type_string, defined by 
> PRINT_TYPE_FUNC_NAME(string) in kernel/trace/trace_probe.c) is the 
> following, it simply passes the respective data to trace_seq_printf with 
> a "%s" format string:
> 
> int PRINT_TYPE_FUNC_NAME(string)(struct trace_seq *s, void *data, void *ent)
> {
>          int len = *(u32 *)data >> 16;
> 
>          if (!len)
>                  trace_seq_puts(s, "(fault)");
>          else
>                  trace_seq_printf(s, "\"%s\"",
>                                   (const char *)get_loc_data(data, ent));
>          return !trace_seq_has_overflowed(s);
> }
> 
> I dug into that function with KGDB and found the following: 'data' holds 
> the size and offset for the member in question, which is 0xf and 0x18, 
> respectively. 'ent' holds the base address for event. When we print the 
> string at ent + 0x18, we can see that the output for 'arg1' will be 
> "update-notifierupdate-notifier"
> 
> Thread 511 hit Breakpoint 6, print_type_string (s=0xffff880078fd1090, 
> name=0xffff880078fe4458 "arg1", data=0xffff88007d01f05c, 
> ent=0xffff88007d01f04c) at 
> /build/linux-EsXT4r/linux-4.18.0/kernel/trace/trace_probe.c:67
> 67	in /build/linux-EsXT4r/linux-4.18.0/kernel/trace/trace_probe.c
> gdb$ p *(uint32_t *) data
> $46 = 0xf0018
> gdb$ p ent
> $47 = (void *) 0xffff88007d01f04c
> gdb$ p ((char *)ent + 0x18)
> $48 = 0xffff88007d01f064 "update-notifierupdate-notifier"
> 
> Moving on printing 'arg2' (e.g., the other $comm string). Here we see 
> that the string in question is at offset 0x27, and if we print that, we 
> see the correct "update-notifier".
> 
> Thread 511 hit Breakpoint 6, print_type_string (s=0xffff880078fd1090, 
> name=0xffff880078fe4d70 "arg2", data=0xffff88007d01f060, 
> ent=0xffff88007d01f04c) at 
> /build/linux-EsXT4r/linux-4.18.0/kernel/trace/trace_probe.c:67
> 67	in /build/linux-EsXT4r/linux-4.18.0/kernel/trace/trace_probe.c
> gdb$ p *(uint32_t *) data
> $49 = 0xf0027
> gdb$ p ((char *)ent + 0x27)
> $50 = 0xffff88007d01f073 "update-notifier"
> 
> Looking at the bytes in memory and the offsets it becomes clear that 
> there is no \0 byte at the end of the first entry (which would need to 
> be at address 0xffff88007d01f064 + 0xf = 0xffff88007d01f073 but instead 
> that's the start address of the second entry which simply gets consumed 
> by the (first) "%s" as well.
> 
> gdb$ x/32x ent
> 0xffff88007d01f04c:	0x00010592	0x00002143	0xe83522a0	0x00007f7f
> 0xffff88007d01f05c:	0x000f0018	0x000f0027	0x61647075	0x6e2d6574
> 0xffff88007d01f06c:	0x6669746f	0x75726569	0x74616470	0x6f6e2d65
> 0xffff88007d01f07c:	0x69666974	0x00007265	0x0045feee	0x00010592
> 0xffff88007d01f08c:	0x00002143	0xe83522a0	0x00007f7f	0x000f0018
> 0xffff88007d01f09c:	0x000f0027	0x61647075	0x6e2d6574	0x6669746f
> 0xffff88007d01f0ac:	0x75726569	0x74616470	0x6f6e2d65	0x69666974
> 0xffff88007d01f0bc:	0x00007265	0x0038806e	0x00010592	0x00002143
> 
> Should we simply also store the terminating \0 at the end of the string? 
> The $comm string is saved by fetch_comm_string (in v4.18) which uses 
> 'strlcpy' and its return value as the size of the respective data... 
> that value however does NOT include the terminating \0 byte (as it's 
> simply the return value of a call to strlen). The same holds for 
> "regular" string arguments where the code uses 'strncpy_from_user' which 
> has the same return value semantics. Or should we use the information in 
> 'len' to only print that many characters?
> 
> As fetch_store_string has changed between v4.18 and v4.20, I could try 
> to reproduce this with a v4.20 kernel but from looking at the code I 
> suspect this should be the problem in v4.20 as well.
> 
> As for $comm only printing "(fault)" I suspect this has to do with 
> commit 533059281ee5 ("tracing: probeevent: Introduce new argument 
> fetching code") as we lost the 'fetch_comm_string' function in that 
> commit and (I think, didn't have the newer kernel running yet) go 
> through 'fetch_store_string' now. This calls 'strncpy_from_user' instead 
> of accessing current->comm directly (and thus does not succeed in 
> fetching it). I'm adding Masami to Cc: as the author of said patch.

Ah, OK. I have to check fetch_store_string() implementation differences
between trace_kprobe.c and trace_uprobe.c. Well, in the uprobes, we may
need more careful steps.

Anyway, that is my fault. I will fix the issue. Hmm, and I may need to
consider to add some test program for uprobes, which including a target
application to be probed.

Thank you!

-- 
Masami Hiramatsu <mhiramat@kernel.org>