No output for kprobes

[pkropachev]

Hi!

I've built bpftools (including bpftrace) for aach64.

# /data/bin/bpftools/bpftrace --info
System
  OS: Linux 5.10.43 #9 SMP PREEMPT Tue Jun 27 12:32:32 UTC 2023
  Arch: aarch64

Build
  version: v0.16.0-96-g58bd
  LLVM: 14.0.6
  unsafe uprobe: no
  bfd: no
  libdw (DWARF support): no

Kernel helpers
  probe_read: yes
  probe_read_str: yes
  probe_read_user: yes
  probe_read_user_str: yes
  probe_read_kernel: yes
  probe_read_kernel_str: yes
  get_current_cgroup_id: yes
  send_signal: yes
  override_return: yes
  get_boot_ns: yes
  dpath: no
  skboutput: no

Kernel features
  Instruction limit: 1000000
  Loop support: yes
  btf: no
  map batch: yes
  uprobe refcount (depends on Build:bcc bpf_attach_uprobe refcount): no

Map types
  hash: yes
  percpu hash: yes
  array: yes
  percpu array: yes
  stack_trace: yes
  perf_event_array: yes

Probe types
  kprobe: yes
  tracepoint: yes
  perf_event: yes
  kfunc: no
  iter:task: no
  iter:task_file: no
  kprobe_multi: no
  raw_tp_special: yes

Tracepoints are caught fine, but I can't get any output for kernel probes (kprobes).

# ./strace -ebpf /data/bin/bpftools/bpftrace -e 'kprobe:do_nanosleep { printf("function is called\n"); }' -v                                    
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=17585, si_uid=0, si_status=0, si_utime=1, si_stime=0} ---
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=17589, si_uid=0, si_status=0, si_utime=0, si_stime=1} ---
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=17591, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
bpf(0x17 /* BPF_??? */, 0x7fccfe4410, 12) = -1 ENOENT (No such file or directory)
bpf(0x17 /* BPF_??? */, 0x7fccfe3f50, 12) = -1 ENOENT (No such file or directory)
INFO: node count: 6
Attaching 1 probe...
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7fccfe40e0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 116) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7fccfe40f0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="libbpf_nametest"}, 64) = 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="printf", map_ifindex=0}, 72) = 3
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0x7fccfe461c, value=0x7fccfe45dc, flags=BPF_ANY}, 32) = 0
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=2, insns=0x7fccfe4030, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="ksys_read", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */}, 128) = 13
bpf(0x1c /* BPF_??? */, 0x7fccfe3ea0, 48) = -1 EINVAL (Invalid argument)
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=12, insns=0xb400007771a0b320, license="GPL", log_level=1, log_size=1000000, log_buf="", kern_version=KERNEL_VERSION(5, 10, 43), prog_flags=0, prog_name="do_nanosleep", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 128) = 14
bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=14, info_len=232 => 208, info=0x7fccfe41d0}}, 16) = 0

Program ID: 86

The verifier log: 
processed 10 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0

Attaching kprobe:do_nanosleep

Currently kernel is built with flags (+ CONFIG_IKHEADERS) specified in check_kernel_features.sh except CONFIG_BPF_JIT, CONFIG_UPROBES and CONFIG_UPROBE_EVENTS.

Could you please suggest what can be a reason of such behavior if you've faced with the similar problem? Or what steps can be done to troubleshot it?

Thanks!

[tnovak]

@pkropachev: that trace looks correct -- first few bpf syscalls are from bpftrace checking which features are available, and then finally the generated BPF code is successfully loaded (if you also trace ioctl calls you should see that program getting attached to a kprobe).

Perhaps do_nanosleep() just isn't firing? Running e.g. sleep 1 in another shell should trigger it. Any issues attaching to other kernel functions?