search

rr-debugger / rr

Record and Replay Framework
http://rr-project.org/
Other
9.12k stars 583 forks source link

Unknown bpf syscall `cmd=36` (BPF_TOKEN_CREATE) #3798

Closed mozzieongit closed 3 weeks ago

mozzieongit commented 1 month ago

Hi, I'm trying to debug a program using BPF with libxdp and libbpf, but rr fails with an unknown bpf syscall. In this case it seems to be BPF_TOKEN_CREATE. Looking at the rr source code (src/record_syscall.cc:prepare_bpf()) and the strace of the example program, I assume the following bpf calls might fail too:

(and I found another call that fails: cmd=15 BPF_OBJ_GET_INFO_BY_FD but it is not used by the example below)

I reproduced this with a minimal-ish example:

main.c

#include <stdlib.h>
#include <xdp/libxdp.h>
#include <net/if.h>
#include <unistd.h>

const char *interface_name = "af";
const char *filename = "kern.o";

int interface_index;
int xsk_map_fd;
int bpf_prog_fd;
struct xdp_program *bpf_prog;

static int load_xdp_program_and_map() {
    struct bpf_map *map;

    DECLARE_LIBXDP_OPTS(bpf_object_open_opts, opts);
    bpf_prog = xdp_program__open_file(filename, NULL, &opts);

    putenv("LIBXDP_SKIP_DISPATCHER=1");
    xdp_program__attach(bpf_prog, interface_index, XDP_MODE_UNSPEC, 0);
    /* fails here ^ */

    /* uses more syscalls that I assume would fail too, so I kept this */
    map = bpf_object__find_map_by_name(xdp_program__bpf_obj(bpf_prog), "xsks_map");
    xsk_map_fd = bpf_map__fd(map);
    return 0;
}

static void unload_xdp_program() {
    DECLARE_LIBBPF_OPTS(bpf_xdp_attach_opts, bpf_opts,
                        .old_prog_fd = bpf_prog_fd);
    bpf_xdp_detach(interface_index, 0, &bpf_opts);
}

int main(int argc, char* argv[]) {
    interface_index = if_nametoindex(interface_name);

    load_xdp_program_and_map();
    /* sleep(5); */
    unload_xdp_program();
    return 0;
}

kern.c

#include <linux/bpf.h>
#include <bpf/bpf_helpers.h>

struct {
  __uint(type, BPF_MAP_TYPE_XSKMAP);
  __type(key, __u32);
  __type(value, __u32);
  __uint(max_entries, 64);
} xsks_map SEC(".maps");

SEC("xdp")
int xdp_nothing(struct xdp_md *ctx) {
  return XDP_PASS;
}

Makefile

.PHONY: all clean

all:    main kern.o

clean:
    rm main kern.o kern.ll

main:   main.c
    clang -g -O0 -lbpf -lxdp -o $@ $<

kern.o: kern.c
    clang -S -target bpf -O2 -emit-llvm -c -g -o ${@:.o=.ll} $<
    llc -march=bpf -filetype=obj -o $@ ${@:.o=.ll}

Error output

[FATAL src/record_syscall.cc:6556:rec_process_syscall_arch()]
 (task 256560 (rec:256560) at time 353)
 -> Assertion `t->regs().syscall_result_signed() == -syscall_state.expect_errno' failed to hold. Expected EINVAL for 'bpf' but got result -95 (errno EOPNOTSUPP); unknown bpf(cmd=36)
Tail of trace dump:
{
  real_time:49666.017732 global_time:333, event:`SYSCALL: faccessat2' (state:ENTERING_SYSCALL) tid:256560, ticks:186714
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x4 rsi:0x7bc6c57bbbbe rdi:0xffffff9c rbp:0x681fffa0 rsp:0x681ffd40 r8:0x0 r9:0x7bc6c5751b20 r10:0x200 r11:0x246 r12:0x4 r13:0x0 r14:0x59fb969d2650 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b7 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017736 global_time:334, event:`SYSCALLBUF_RESET' tid:256560, ticks:186714
}
{
  real_time:49666.017752 global_time:335, event:`SYSCALL: faccessat2' (state:EXITING_SYSCALL) tid:256560, ticks:186714
rax:0xfffffffffffffffe rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x4 rsi:0x7bc6c57bbbbe rdi:0xffffff9c rbp:0x681fffa0 rsp:0x681ffd40 r8:0x0 r9:0x7bc6c5751b20 r10:0x200 r11:0x246 r12:0x4 r13:0x0 r14:0x59fb969d2650 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1b7 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017822 global_time:336, event:`SYSCALLBUF_FLUSH' tid:256560, ticks:192661
  { syscall:'uname', ret:0x0, size:0x196 }
  { syscall:'openat', ret:0x3, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0x1d, size:0x2d }
  { syscall:'fcntl', ret:0x1, size:0x10 }
  { syscall:'fstat', ret:0x0, size:0xa0 }
  { syscall:'pread64', ret:0x40, size:0x50, desched:1 }
  { syscall:'pread64', ret:0x3c0, size:0x3d0, desched:1 }
  { syscall:'pread64', ret:0x6b, size:0x7b, desched:1 }
  { syscall:'pread64', ret:0x1c8, size:0x1d8, desched:1 }
  { syscall:'pread64', ret:0x210, size:0x220, desched:1 }
  { syscall:'pread64', ret:0x7d, size:0x8d, desched:1 }
  { syscall:'pread64', ret:0x4b0, size:0x4c0, desched:1 }
  { syscall:'pread64', ret:0x150, size:0x160, desched:1 }
  { syscall:'pread64', ret:0x7c, size:0x8c, desched:1 }
  { syscall:'pread64', ret:0x4, size:0x14, desched:1 }
  { syscall:'pread64', ret:0x8, size:0x18, desched:1 }
}
{
  real_time:49666.017842 global_time:337, event:`PATCH_SYSCALL' tid:256560, ticks:192661
rax:0x1 rbx:0x40 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7fff9444e1f0 rdi:0x2 rbp:0x7fff9444e090 rsp:0x7fff9444e068 r8:0x73 r9:0x0 r10:0x0 r11:0x246 r12:0x40 r13:0x7fff9444e1f0 r14:0x7bc6c57524e0 r15:0x7bc6c574ff00 rip:0x7bc6c5678502 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7bc6c5453280 gs_base:0x0
  { tid:256560, addr:0x7bc6c57d95e0, length:0x5e }
  { tid:256560, addr:0x7bc6c5678502, length:0x8 }
}
{
  real_time:49666.017846 global_time:338, event:`SYSCALLBUF_RESET' tid:256560, ticks:192661
}
{
  real_time:49666.017864 global_time:339, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:256560, ticks:192680
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7fff9444e1f0 rdi:0x2 rbp:0x681fffa0 rsp:0x681ffd40 r8:0x73 r9:0x0 r10:0x0 r11:0x246 r12:0x7fff9444e1f0 r13:0x40 r14:0x0 r15:0x7bc6c574ff00 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017883 global_time:340, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:256560, ticks:192680
rax:0x40 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x40 rsi:0x7fff9444e1f0 rdi:0x2 rbp:0x681fffa0 rsp:0x681ffd40 r8:0x73 r9:0x0 r10:0x0 r11:0x246 r12:0x7fff9444e1f0 r13:0x40 r14:0x0 r15:0x7bc6c574ff00 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017911 global_time:341, event:`SYSCALLBUF_FLUSH' tid:256560, ticks:193532
  { syscall:'pread64', ret:0x5ac, size:0x5bc, desched:1 }
  { syscall:'pread64', ret:0x840, size:0x850, desched:1 }
  { syscall:'pread64', ret:0x1c, size:0x2c, desched:1 }
}
{
  real_time:49666.017915 global_time:342, event:`SYSCALL: write' (state:ENTERING_SYSCALL) tid:256560, ticks:193532
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x43 rsi:0x7fff9444e1f0 rdi:0x2 rbp:0x681fffa0 rsp:0x681ffd40 r8:0x73 r9:0x0 r10:0x0 r11:0x246 r12:0x7fff9444e1f0 r13:0x43 r14:0x0 r15:0x7bc6c574ff00 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017918 global_time:343, event:`SYSCALLBUF_RESET' tid:256560, ticks:193532
}
{
  real_time:49666.017934 global_time:344, event:`SYSCALL: write' (state:EXITING_SYSCALL) tid:256560, ticks:193532
rax:0x43 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x43 rsi:0x7fff9444e1f0 rdi:0x2 rbp:0x681fffa0 rsp:0x681ffd40 r8:0x73 r9:0x0 r10:0x0 r11:0x246 r12:0x7fff9444e1f0 r13:0x43 r14:0x0 r15:0x7bc6c574ff00 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x1 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017964 global_time:345, event:`SYSCALL: memfd_create' (state:ENTERING_SYSCALL) tid:256560, ticks:197626
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x59fb969da950 rsi:0x1 rdi:0x7bc6c57ba55b rbp:0x681fffa0 rsp:0x681ffd40 r8:0x1 r9:0x59fb969d2650 r10:0x0 r11:0x246 r12:0x59fb969da150 r13:0x59fb969d49d9 r14:0x7c r15:0x4 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x13f fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.017980 global_time:346, event:`SYSCALL: memfd_create' (state:EXITING_SYSCALL) tid:256560, ticks:197626
rax:0x5 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x59fb969da950 rsi:0x1 rdi:0x7bc6c57ba55b rbp:0x681fffa0 rsp:0x681ffd40 r8:0x1 r9:0x59fb969d2650 r10:0x0 r11:0x246 r12:0x59fb969da150 r13:0x59fb969d49d9 r14:0x7c r15:0x4 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x13f fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.018024 global_time:347, event:`PATCH_SYSCALL' tid:256560, ticks:198498
rax:0x9 rbx:0x0 rcx:0xffffffffffffffff rdx:0x3 rsi:0x1000 rdi:0x0 rbp:0x7fff9444e330 rsp:0x7fff9444e320 r8:0xffffffff r9:0x0 r10:0x21 r11:0x246 r12:0x21 r13:0x59fb969d9564 r14:0x7c r15:0x59fb969da150 rip:0x7bc6c5680f4a eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0xffffffffffffffff fs_base:0x7bc6c5453280 gs_base:0x0
  { tid:256560, addr:0x7bc6c57d963e, length:0x5e }
  { tid:256560, addr:0x7bc6c5680f4a, length:0x8 }
}
{
  real_time:49666.018044 global_time:348, event:`SYSCALL: mmap' (state:ENTERING_SYSCALL) tid:256560, ticks:198507
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x3 rsi:0x1000 rdi:0x0 rbp:0x681fffa0 rsp:0x681ffd40 r8:0xffffffff r9:0x0 r10:0x21 r11:0x246 r12:0x21 r13:0x59fb969d9564 r14:0x7c r15:0x59fb969da150 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.018131 global_time:349, event:`SYSCALL: mmap' (state:EXITING_SYSCALL) tid:256560, ticks:198507
rax:0x7bc6c5810000 rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x3 rsi:0x1000 rdi:0x0 rbp:0x681fffa0 rsp:0x681ffd40 r8:0xffffffff r9:0x0 r10:0x21 r11:0x246 r12:0x21 r13:0x59fb969d9564 r14:0x7c r15:0x59fb969da150 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x9 fs_base:0x7bc6c5453280 gs_base:0x0
  { map_file:"<ZERO>", addr:0x7bc6c5810000, length:0x1000, prot_flags:"rw-s", file_offset:0x0, device:1, inode:359740, data_file:"", data_offset:0x0, file_size:0x1000 }
}
{
  real_time:49666.018174 global_time:350, event:`SYSCALLBUF_FLUSH' tid:256560, ticks:203777
  { syscall:'close', ret:0x0, size:0x10 }
  { syscall:'openat', ret:0x3, size:0x10, desched:1 }
  { syscall:'readlinkat', ret:0xb, size:0x1b }
}
{
  real_time:49666.018178 global_time:351, event:`SYSCALL: bpf' (state:ENTERING_SYSCALL) tid:256560, ticks:203777
rax:0xffffffffffffffda rbx:0x681fffa0 rcx:0xffffffffffffffff rdx:0x8 rsi:0x7fff9444f340 rdi:0x24 rbp:0x681fffa0 rsp:0x681ffd40 r8:0x0 r9:0x300000000 r10:0x73 r11:0x246 r12:0x7bc6c57ba942 r13:0x4 r14:0x1 r15:0x0 rip:0x70000002 eflags:0x246 cs:0x33 ss:0x2b ds:0x0 es:0x0 fs:0x0 gs:0x0 orig_rax:0x141 fs_base:0x7bc6c5453280 gs_base:0x0
}
{
  real_time:49666.018182 global_time:352, event:`SYSCALLBUF_RESET' tid:256560, ticks:203777
}
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x5a)[0x5aab8b44327a]
rr(_ZN2rr15emergency_debugEPNS_4TaskE+0x15e)[0x5aab8b56be7e]
rr(+0x21ca4a)[0x5aab8b560a4a]
rr(+0x21cc3f)[0x5aab8b560c3f]
rr(+0x21cc79)[0x5aab8b560c79]
rr(+0x1aec9c)[0x5aab8b4f2c9c]
rr(_ZN2rr19rec_process_syscallEPNS_10RecordTaskE+0x13d)[0x5aab8b517bed]
rr(_ZN2rr13RecordSession21syscall_state_changedEPNS_10RecordTaskEPNS0_9StepStateE+0x944)[0x5aab8b52f964]
rr(_ZN2rr13RecordSession11record_stepEv+0x606)[0x5aab8b533276]
rr(_ZN2rr13RecordCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0xe14)[0x5aab8b537b14]
rr(main+0x199)[0x5aab8b41dbc9]
/usr/lib/libc.so.6(+0x25c88)[0x76fe5d15dc88]
/usr/lib/libc.so.6(__libc_start_main+0x8c)[0x76fe5d15dd4c]
rr(_start+0x2e)[0x5aab8b41e1be]
=== End rr backtrace
rocallahan commented 3 weeks ago

116b23a3827700704e79e7c54cda9c492ab153c1

mozzieongit commented 1 week ago

Awesome, thanks for implementing that so quickly. The BPF syscalls seem to work, but only when I pass --no-syscall-buffer. If I omit that flag I get the following error:

src/preload/syscallbuf.c:688: Fatal error: Failed to perf_event_open
rocallahan commented 1 week ago

Hmm. What kernel version? What's the value of /proc/sys/kernel/perf_event_paranoid?

mozzieongit commented 1 week ago

Oh, I forgot about that after rebooting. It was on 2 I set it to 1 again and it works now without the flag. Thanks for the reminder and sorry about the extra noise.

rr is crashing during the replay now though. I'll open a dedicated issue once I narrowed down the cause.