Re: uprobes: bug in comm/string output?

From: Andreas Ziegler
Date: Wed Jan 16 2019 - 05:16:16 EST


Hi,

thanks for your reply!

On 1/16/19 11:00 AM, Masami Hiramatsu wrote:
On Tue, 15 Jan 2019 14:36:48 +0100
Andreas Ziegler <andreas.ziegler@xxxxxx> 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.


yes, kprobes work because they use strncpy_from_unsafe which *includes* the null byte in its return value... the fact that both are called strncpy_* but behave differently is really annoying...

I just sent a patch for this case half an hour ago which simply adds 1 to the returned value for uprobes if it didn't hit the maximum allowed length.


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.


I went into this a bit deeper today, and right now it is simply failing to parse the code because there is no FETCH_OP_COMM case in process_fetch_insn() for uprobes so that will return -EILSEQ, leading to a make_data_loc(0, ...) in store_trace_args(). If we just add FETCH_OP_COMM and let val point to current->comm (that's what trace_kprobe.c does), we get an -EFAULT return value from fetch_store_string because strncpy_from_user() checks if the argument is in user space.

So I think we might need a special case for that, something like FETCH_OP_ST_COMM_STRING which is only used for FETCH_OP_COMM and copies current->comm over to the dynamic area. The implementation could be similar to the old fetch_comm_string implementation before your rewrite.

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!


Thanks, let me know if I can help you.

Andreas

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature