Handle strings for bpf_trace_printk() about bcc

[drzaeus77]

This works now with latest net-next kernel. No changes to BCC required.

[drzaeus77]

@brendangregg By chance did you find time to test this?

[brendangregg]

Some success. Here's an example that works:

open_exec.c:

#include <uapi/linux/ptrace.h>

void run_exec(struct pt_regs *ctx, const char *name)
{
    bpf_trace_printk("executed %s\n", name);
}

open_exec.py:

#!/usr/bin/python

from bcc import BPF

# load BPF program
b = BPF(src_file="open_exec.c")
b.attach_kprobe(event="open_exec", fn_name="run_exec")

# format output
while 1:
    (task, pid, cpu, flags, ts, msg) = b.trace_readline_fields()
    print("got: %s" % msg)

output:

# ./open_exec.py 
got: executed /bin/bash
got: executed /bin/bash
got: executed /lib64/ld-linux-x86-64.so.2
got: executed /lib64/ld-linux-x86-64.so.2
got: executed /lib64/ld-linux-x86-64.so.2
got: executed /lib64/ld-linux-x86-64.so.2
got: executed /lib64/ld-linux-x86-64.so.2
got: executed /lib64/ld-linux-x86-64.so.2
[...]

Now for an example that doesn't seem to work:

exec.c:

#include <linux/fs.h>

int run_exec(struct pt_regs *ctx, struct filename *filename)
{
    void *name = 0;

    bpf_probe_read(&name, sizeof(name), (char *)filename->name);
    bpf_trace_printk("executed %s\n", name);
    return 0;
}

exec.py:

#!/usr/bin/python

from bcc import BPF

# load BPF program
b = BPF(src_file="exec.c")
b.attach_kprobe(event="do_execve", fn_name="run_exec")
b.attach_kprobe(event="SyS_execve", fn_name="run_exec")

# format output
while 1:
    (task, pid, cpu, flags, ts, msg) = b.trace_readline_fields()
    print("got: %s" % msg)

output:

# ./exec.py 
got: executed
got: executed
got: executed
got: executed
got: executed
got: executed
got: executed
[...]

[brendangregg]

minor comment: if I use more than one %s, it silently fails. I hope support for multiple %s's (one day) is easier than supporting an error. :)

[brendangregg]

... and why I didn't match Alexei's original example:

# ./exec.py 
/home/bgregg-buildtest/bcc/examples/exec.c:7:38: error: cannot take the address of an rvalue of type 'char *'
        bpf_probe_read(&name, sizeof(name), &(char *)filename->name);
                                            ^~~~~~~~~~~~~~~~~~~~~~~

[drzaeus77]

I think that example in the commit message of net-next is a mix of BCC and unadulterated C.

If you choose to attach to SyS_execve, the argument should be a const char * not a struct filename *.

#include <linux/fs.h>

int run_exec(struct pt_regs *ctx, const char *filename) {
    bpf_trace_printk("executed %s\n", filename);
    return 0;
}

#!/usr/bin/python

from bcc import BPF

# load BPF program
b = BPF(src_file="exec.c")
#b.attach_kprobe(event="do_execve", fn_name="run_exec")
b.attach_kprobe(event="SyS_execve", fn_name="run_exec")

# format output
while 1:
    (task, pid, cpu, flags, ts, msg) = b.trace_readline_fields()
    print("got: %s" % msg)

$ sudo python exec.py 
got: executed /bin/sh
got: executed /bin/sh
got: executed /usr/bin/byobu-status
got: executed /usr/bin/byobu-status

[drzaeus77]

Also, when I attach to do_exec (which does have the struct filename * argument), nothing prints. Possibly optimized out by the compiler.

[4ast]

the example I gave in kernel commit log was for normal clang without bcc fancy rewriter :)
When bcc sees 'filename->name' it magically does bpf_probe_read underneath.
To trick bcc to avoid automatic bpf_probe_read, try type-casting it:
prog = """
#include <linux/fs.h>
int foo(struct pt_regs *ctx, struct filename *filename) {
void *name = 0;

// below is equivalent to 'filename->name'
bpf_probe_read(&name, sizeof(name), &(((struct filename *)filename)->name));
bpf_trace_printk("executed %s\n", name);
return 0;
}
"""
b = BPF(text=prog)
b.attach_kprobe(event="do_execve", fn_name="foo")
b.trace_print(fmt="{0}-{1} {5}")

works fine for me with output:
bash-9696 executed /bin/ls
bash-9697 executed /bin/ls
bash-9698 executed /bin/ls

[4ast]

multiple %s
they are caught and rejected.
bpf_trace_prinkt() returns -EINVAL in such case.
I don't think it will support it any time soon.
We already burning 64 bytes of stack for one %s. Burning the double would be excessive.

bpf_output_trace_data(void *buf, int buf_size);
helper is on the way and that will be the proper way to stream data to userspace.
bpf_trace_printk() is really debugging only.

[brendangregg]

@drzaeus77 ah, thanks, yes, I should have looked at the args of sys_execve().

do_execve() isn't firing for me; I assume a different codepath is taken. Here's my execs:

# /apps/perf-tools/bin/funccount '*exec*'
Tracing "*exec*"... Ctrl-C to end.
^C
FUNC                              COUNT
get_close_on_exec                     1
set_close_on_exec                    24
apparmor_bprm_secureexec             36
cap_bprm_secureexec                  36
do_close_on_exec                     36
flush_old_exec                       36
install_exec_creds                   36
proc_exec_connector                  36
security_bprm_secureexec             36
setup_new_exec                       36
do_execveat_common.isra.31           37
prepare_exec_creds                   37
sched_exec                           37
SyS_execve                           37
open_exec                            44
generic_exec_single                  49
find_worker_executing_work           61
do_open_execat                       81

Ending tracing...

which reminds me: I should rewrite funccount using bcc (by tweaking the vfscount example).

[brendangregg]

I'll close this issue -- this should be ok for now. Any idea when these patches move to mainline?

[4ast]

net-next was already pulled into 4.3