uprobes: bug in comm/string output?

[Andreas Ziegler]

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).

On the "standard" kernel shipped with Ubuntu 18.04 (4.18) printing $comm works 
but also "accumulates" (in lack of a better word) the later string arguments in 
the earlier output arguments, so for the probe above arg1 would be 
"testtestlibc.so.6libc.so.6", arg2 would be "testlibc.so.6libc.so.6" and 
arg3/arg4 will be the same as in the output above.

Is there anything in the documentation why multiple string outputs might not 
work with uprobes? Am I installing the uprobe wrong? Or is this a bug?

I found that the kprobe selftest at 
tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args_string.tc contains a 
similar situation for kprobes (it prints the parameter two times) which works 
fine on the same system.

Regards,

Andreas

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