Debugging eBPF was: Re: [PATCH bpf-next 0/8] tools: bpftool: add probes for system and device

[Arnaldo Carvalho de Melo <acme@kernel.org>]

Em Thu, Dec 13, 2018 at 10:03:59AM -0300, Arnaldo Carvalho de Melo escreveu:
> libbpf: failed to load program 'raw_syscalls:sys_enter'
> libbpf: failed to load object 'tools/perf/examples/bpf/augmented_raw_syscalls.c'
> bpf: load objects failed: err=-4009: (Incorrect kernel version)
> event syntax error: 'tools/perf/examples/bpf/augmented_raw_syscalls.c'
>                      \___ Failed to load program for unknown reason
> 
> (add -v to see detail)
> Run 'perf list' for a list of valid events
> 
>  Usage: perf trace [<options>] [<command>]
>     or: perf trace [<options>] -- <command> [<options>]
>     or: perf trace record [<options>] [<command>]
>     or: perf trace record [<options>] -- <command> [<options>]
> 
>     -e, --event <event>   event/syscall selector. use 'perf list' to list available events
> [acme@quaco perf]$ 
> 
> Ok, out to figure this out :-)

I've changed the subject to better reflect the change in discussion,
which I think is worth as it was another topic discussed at LPC, how to
debug when somthing goes awry:

So I first tried with:

$ strace -e bpf perf trace -v -a -e open*,tools/perf/examples/bpf/augmented_raw_syscalls.o
<SNIP>
bpf: config program 'raw_syscalls:sys_enter'
bpf: config program 'raw_syscalls:sys_exit'
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8, map_flags=0, inner_map_fd=0, map_name="__bpf_stdout__", map_ifindex=0}, 72) = 3
libbpf: create map __bpf_stdout__: fd=3
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8, map_flags=0, inner_map_fd=0, map_name="__augmented_sys", map_ifindex=0}, 72) = 4
libbpf: create map __augmented_syscalls__: fd=4
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=1, max_entries=512, map_flags=0, inner_map_fd=0, map_name="syscalls", map_ifindex=0}, 72) = 5
libbpf: create map syscalls: fd=5
bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_HASH, key_size=4, value_size=1, max_entries=64, map_flags=0, inner_map_fd=0, map_name="pids_filtered", map_ifindex=0}, 72) = 6
libbpf: create map pids_filtered: fd=6
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_TRACEPOINT, insn_cnt=55, insns=0x11ec6e0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(4, 20, 0), prog_flags=0, prog_name="sys_enter", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 72) = -1 EPERM (Operation not permitted)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_TRACEPOINT, insn_cnt=55, insns=0x11ec6e0, license="GPL", log_level=1, log_size=262144, log_buf="", kern_version=KERNEL_VERSION(4, 20, 0), prog_flags=0, prog_name="sys_enter", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 72) = -1 EPERM (Operation not permitted)
libbpf: load bpf program failed: Operation not permitted
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=55, insns=0x11ec6e0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(4, 20, 0), prog_flags=0, prog_name="sys_enter", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 72) = -1 EPERM (Operation not permitted)
libbpf: failed to load program 'raw_syscalls:sys_enter'
libbpf: failed to load object 'tools/perf/examples/bpf/augmented_raw_syscalls.o'
bpf: load objects failed: err=-4009: (Incorrect kernel version)
event syntax error: 'tools/perf/examples/bpf/augmented_raw_syscalls.o'
                     \___ Failed to load program for unknown reason


So it can create the maps, but not attach the programs to tracepoints,
ok, now lets switch to what is happening in the kernel side:

[acme@quaco perf]$ perf ftrace -G bpf_prog_load perf trace -v -a -e open*,tools/perf/examples/bpf/augmented_raw_syscalls.o
ftrace only works for root!
[acme@quaco perf]$

Oops, so lets try as root, doing it system wide, then start the 'perf
trace' part:

[root@quaco ~]# perf ftrace -G bpf_prog_load -a
 5)               |  bpf_prog_load() {
 5)               |    __check_object_size() {
 5)   0.110 us    |      __virt_addr_valid();
 5)   0.111 us    |      check_stack_object();
 5)   0.534 us    |    }
 5)               |    capable() {
 5)               |      ns_capable_common() {
 5)               |        security_capable() {
 5)   0.102 us    |          cap_capable();
 5)   0.336 us    |        }
 5)   0.773 us    |      }
 5)   0.989 us    |    }
 5) + 18.444 us   |  }
 5)               |  bpf_prog_load() {
 5)               |    __check_object_size() {
 5)   0.117 us    |      __virt_addr_valid();
 5)   0.116 us    |      check_stack_object();
 5)   0.575 us    |    }
 5)               |    capable() {
 5)               |      ns_capable_common() {
 5)               |        security_capable() {
 5)   0.104 us    |          cap_capable();
 5)   0.318 us    |        }
 5)   0.519 us    |      }
 5)   0.722 us    |    }
 5)   1.671 us    |  }
 5)               |  bpf_prog_load() {
 5)               |    __check_object_size() {
 5)   0.105 us    |      __virt_addr_valid();
 5)   0.103 us    |      check_stack_object();
 5)   0.527 us    |    }
 5)               |    capable() {
 5)               |      ns_capable_common() {
 5)               |        security_capable() {
 5)   0.099 us    |          cap_capable();
 5)   0.315 us    |        }
 5)   0.520 us    |      }
 5)   0.715 us    |    }
 5)   5.111 us    |  }
 
 Ok, not that helpful, but should be this one:

         if (type != BPF_PROG_TYPE_SOCKET_FILTER &&
             type != BPF_PROG_TYPE_CGROUP_SKB &&
            !capable(CAP_SYS_ADMIN))
                return -EPERM;

I'll update the error message accordingly :-/

Only root can attach eBPF programs to tracepoints.

Would be really good if we could have a more restricted program type to
attach to tracepoints, one that would be able to run only in the context
of their threads and access only the pointers in the tracepoints, that
way the 'perf trace' augmented syscalls code would be usable for
non-root users just like the other 'perf' commands are, allowing us to,
as with root, to copy the pointer arguments, like:

[root@quaco ~]# cd ~acme/git/perf/tools/perf/examples/bpf
[root@quaco bpf]# perf trace -e open*,augmented_raw_syscalls.o cat /etc/passwd > /dev/null
     0.000 ( 0.007 ms): cat/29941 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC           ) = 3
     0.018 ( 0.004 ms): cat/29941 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC           ) = 3
     0.185 ( 0.005 ms): cat/29941 openat(dfd: CWD, filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
     0.223 ( 0.047 ms): cat/29941 openat(dfd: CWD, filename: /etc/passwd                                ) = 3

Without that we are back to just what is present in the tracepoints, the
pointers:

[root@quaco bpf]# perf trace -e open* cat /etc/passwd > /dev/null
     0.000 ( 0.006 ms): cat/29946 openat(dfd: CWD, filename: 0xa354e8b3, flags: CLOEXEC                 ) = 3
     0.017 ( 0.004 ms): cat/29946 openat(dfd: CWD, filename: 0xa3558d00, flags: CLOEXEC                 ) = 3
     0.217 ( 0.005 ms): cat/29946 openat(dfd: CWD, filename: 0xa34d6a20, flags: CLOEXEC                 ) = 3
     0.260 ( 0.003 ms): cat/29946 openat(dfd: CWD, filename: 0xcd70cd69                                 ) = 3
[root@quaco bpf]# file augmented_raw_syscalls.o
augmented_raw_syscalls.o: ELF 64-bit LSB relocatable, eBPF, version 1 (SYSV), not stripped
[root@quaco bpf]#

- Arnaldo