When loading eBPF binary with bpftool, the 'bpf_trace_printk' seems no output to '/sys/kernel/debug/tracing/trace_pipe'

[Songchunbo]

Q: When trying 'libbpf/libbpf-bootstrap' project. I tried to load the generated BPF prog with 'bpftool', the 'bpf_trace_printk' seems not output to '/sys/kernel/debug/tracing/trace_pipe'. How to fix it or debug it?

• Testing context:

# bpftool -V
bpftool v7.5.0
using libbpf v1.5
features: skeletons
# uname -a
Linux VirtualBox 5.15.0-102-generic #112~20.04.1-Ubuntu SMP Thu Mar 14 14:28:24 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
# clang --version
Ubuntu clang version 12.0.0-3ubuntu1~20.04.5
Target: x86_64-pc-linux-gnu
Thread model: posix
InstalledDir: /usr/bin

• Testing process

1. Attempt to run the 'kprobe' command to load the 'kprobe.bpf.o' BPF prog, who monitors the file remove events. The file remove events can be inspected at '/sys/kernel/debug/tracing/trace_pipe'.

libbpf-bootstrap/examples/c$ sudo ./kprobe
libbpf: loading object 'kprobe_bpf' from buffer
libbpf: elf: section(2) .symtab, size 240, link 1, flags 0, type=2
libbpf: elf: section(3) kprobe/do_unlinkat, size 152, link 0, flags 6, type=1
libbpf: sec 'kprobe/do_unlinkat': found program 'do_unlinkat' at insn offset 0 (0 bytes), code size 19 insns (152 bytes)
libbpf: elf: section(4) kretprobe/do_unlinkat, size 88, link 0, flags 6, type=1
libbpf: sec 'kretprobe/do_unlinkat': found program 'do_unlinkat_exit' at insn offset 0 (0 bytes), code size 11 insns (88 bytes)
libbpf: elf: section(5) license, size 13, link 0, flags 3, type=1
libbpf: license of kprobe_bpf is Dual BSD/GPL
libbpf: elf: section(6) .rodata, size 72, link 0, flags 2, type=1
libbpf: elf: section(7) .relkprobe/do_unlinkat, size 16, link 2, flags 0, type=9
libbpf: elf: section(8) .relkretprobe/do_unlinkat, size 16, link 2, flags 0, type=9
libbpf: elf: section(9) .BTF, size 1468, link 0, flags 0, type=1
libbpf: elf: section(10) .BTF.ext, size 364, link 0, flags 0, type=1
libbpf: looking for externs among 10 symbols...
libbpf: collected 0 externs total
libbpf: map 'kprobe_b.rodata' (global data): at sec_idx 6, offset 0, flags 80.
libbpf: map 0 is "kprobe_b.rodata"
libbpf: sec '.relkprobe/do_unlinkat': collecting relocation for section(3) 'kprobe/do_unlinkat'
libbpf: sec '.relkprobe/do_unlinkat': relo #0: insn #12 against '.rodata'
libbpf: prog 'do_unlinkat': found data map 0 (kprobe_b.rodata, sec 6, off 0) for insn 12
libbpf: sec '.relkretprobe/do_unlinkat': collecting relocation for section(4) 'kretprobe/do_unlinkat'
libbpf: sec '.relkretprobe/do_unlinkat': relo #0: insn #3 against '.rodata'
libbpf: prog 'do_unlinkat_exit': found data map 0 (kprobe_b.rodata, sec 6, off 0) for insn 3
libbpf: object 'kprobe_bpf': failed (-22) to create BPF token from '/sys/fs/bpf', skipping optional step...
libbpf: loaded kernel BTF from ''
libbpf: sec 'kprobe/do_unlinkat': found 2 CO-RE relocations
libbpf: CO-RE relocating [2] struct pt_regs: found target candidate [224] struct pt_regs in [vmlinux]
libbpf: prog 'do_unlinkat': relo #0: <byte_off> [2] struct pt_regs.si (0:13 @ offset 104)
libbpf: prog 'do_unlinkat': relo #0: matching candidate #0 <byte_off> [224] struct pt_regs.si (0:13 @ offset 104)
libbpf: prog 'do_unlinkat': relo #0: patched insn #0 (LDX/ST/STX) off 104 -> 104
libbpf: CO-RE relocating [7] struct filename: found target candidate [1976] struct filename in [vmlinux]
libbpf: prog 'do_unlinkat': relo #1: <byte_off> [7] struct filename.name (0:0 @ offset 0)
libbpf: prog 'do_unlinkat': relo #1: matching candidate #0 <byte_off> [1976] struct filename.name (0:0 @ offset 0)
libbpf: prog 'do_unlinkat': relo #1: patched insn #3 (ALU/ALU64) imm 0 -> 0
libbpf: sec 'kretprobe/do_unlinkat': found 1 CO-RE relocations
libbpf: prog 'do_unlinkat_exit': relo #0: <byte_off> [2] struct pt_regs.ax (0:10 @ offset 80)
libbpf: prog 'do_unlinkat_exit': relo #0: matching candidate #0 <byte_off> [224] struct pt_regs.ax (0:10 @ offset 80)
libbpf: prog 'do_unlinkat_exit': relo #0: patched insn #0 (LDX/ST/STX) off 80 -> 80
libbpf: map 'kprobe_b.rodata': created successfully, fd=3
Successfully started! Please run `sudo cat /sys/kernel/debug/tracing/trace_pipe` to see output of the BPF programs.
............
$  

# cat /sys/kernel/debug/tracing/trace_pipe

           <...>-9800    [003] d...1 67112.921168: bpf_trace_printk: KPROBE ENTRY pid = 9800, filename = aaa

           <...>-9800    [003] d...1 67112.921306: bpf_trace_printk: KPROBE EXIT: pid = 9800, ret = 0

2. Try o load 'kprobe.bpf.o' with bpftool, there's no output in '/sys/kernel/debug/tracing/trace_pipe'

libbpf-bootstrap/examples/c# bpftool prog load .output/kprobe.bpf.o /sys/fs/bpf/kprobe
libbpf-bootstrap/examples/c# bpftool prog list
1147: kprobe  name do_unlinkat  tag 00e8d3ef8d99f9ec  gpl
    loaded_at 2024-05-06T15:06:02+0800  uid 0
    xlated 152B  jited 96B  memlock 4096B  map_ids 261
    btf_id 326

libbpf-bootstrap/examples/c# bpftool prog dump xlated id 1147
int do_unlinkat(struct pt_regs * ctx):
; int BPF_KPROBE(do_unlinkat, int dfd, struct filename *name)
   0: (79) r6 = *(u64 *)(r1 +104)
; pid = bpf_get_current_pid_tgid() >> 32;
   1: (85) call bpf_get_current_pid_tgid#161008
   2: (bf) r7 = r0
   3: (b7) r1 = 0
   4: (0f) r6 += r1
   5: (bf) r1 = r10
;
   6: (07) r1 += -8
; filename = BPF_CORE_READ(name, name);
   7: (b7) r2 = 8
   8: (bf) r3 = r6
   9: (85) call bpf_probe_read_kernel#-69648
; filename = BPF_CORE_READ(name, name);
  10: (79) r4 = *(u64 *)(r10 -8)
; pid = bpf_get_current_pid_tgid() >> 32;
  11: (77) r7 >>= 32
; bpf_printk("KPROBE ENTRY pid = %d, filename = %s\n", pid, filename);
  12: (18) r1 = map[id:261][0]+0
  14: (b7) r2 = 38
  15: (bf) r3 = r7
  16: (85) call bpf_trace_printk#-66576
; int BPF_KPROBE(do_unlinkat, int dfd, struct filename *name)
  17: (b7) r0 = 0
  18: (95) exit

[qmonnet]

Hi and thanks, but please do not use issues in this repository to ask generic questions about BPF or how to use bpftool. Your question is not related to how bpftool works, let alone to something specific to the GitHub mirror repository. In the future, please consider other channels (check out the “Community” menu at the top of https://ebpf.io/ for some pointers, if necessary).

As for your question, what you observe is because bpftool loads the program but does not attach it, so your program does not run and never produce logs in the trace pipe. This is something you could check by checking whether your program does anything else (such as updating BPF map entries), or by checking the number of times the program ran in the program statistics dumped by bpftool prog show when stats are enabled, or if I remember correctly, by checking whether the program is attached to either a perf event with bpftool perf list or a BPF link with bpftool link list. Bpftool does not support attaching a tracing program that it loaded in a previous step. However, it can attach right after loading under certain circumstances, search for the autoattach keyword in the man pages.

[Songchunbo]

Hi, apologies for the inconvenience. I'll post it to the eBPF community channel.

Regarding your suggestion, I attempted to enable BPF stats using the command sysctl -w kernel.bpf_stats_enabled=1, but there were no stats data when dumping the program via bpftool prog show. Furthermore, executing bpftool perf list or bpftool link list yielded no output. Also, there are no mentions of the autoattach and auto keywords in the bpftool man pages.

# bpftool prog show  

1147: kprobe  name do_unlinkat  tag 00e8d3ef8d99f9ec  gpl
    loaded_at 2024-05-07T04:39:10+0800  uid 0
    xlated 152B  jited 96B  memlock 4096B  map_ids 261
    btf_id 326

# bpftool perf list
# bpftool link list
#

[qmonnet]

Hi, apologies for the inconvenience. I'll post it to the eBPF community channel.

No inconvenience at all, I just want to avoid Issues in this repo to turn into a Q&A or support channel.

Regarding your suggestion, I attempted to enable BPF stats using the command sysctl -w kernel.bpf_stats_enabled=1, but there were no stats data when dumping the program via bpftool prog show.

If both counters (time spent running and run count) remain at 0, bpftool doesn't display them. So that would confirm your program doesn't run.

Furthermore, executing bpftool perf list or bpftool link list yielded no output.

This confirms the program is not attached. Compare with the output from when you load your programs through ./kprobe

Also, there are no mentions of the autoattach and auto keywords in the bpftool man pages.

This option is relatively recent (bpftool 7.1) and might not be available on the man page shipped on your distro. See here.

[Songchunbo]

Thanks Quentin , with the ./kprobe execution. It has the output results . So it seems the program is not attached via 'bpftool' loading. I'll check the man pages for autoattach usage. But why the program is not attached when using bpftool prog load

root@-VirtualBox:~# bpftool perf list
pid 12393  fd 7: prog_id 1227  kprobe  func do_unlinkat  offset 0
pid 12393  fd 9: prog_id 1229  kretprobe  func do_unlinkat  offset 0
root@-VirtualBox:~# bpftool link list
38: perf_event  prog 1227
    bpf_cookie 0
    pids kprobe(12393)
39: perf_event  prog 1229
    bpf_cookie 0
    pids kprobe(12393)

[qmonnet]

Loading and attaching programs are two separate steps, although many user space tools usually handle both at the same time.

Bpftool has commands to attach some program types, for example XDP programs or some other specific types of programs, but not tracing programs.

But why the program is not attached when using bpftool prog load

Because historically, this was not possible. Tracing programs needed to be attached to a perf event, and they needed a process to keep the file descriptor to that perf event open to remain attached. In other words, if bpftool attached BPF tracing programs, they'd be detached as soon as bpftool returned.

Now that BPF links exist, this requirement is no longer valid and we could attach programs with bpftool. But people don't usually need to attach programs that have been loaded from a previous bpftool invocation, and we just haven't implemented it so far. Last time someone wanted to load+attach they contributed the autoattach feature, which tells bpftool to do both steps at the same time, provided libbpf can derive the right attach point from the ELF section names; this should get you covered for your use case, I expect.

[Songchunbo]

Tried below instruction, the /sys/kernel/debug/tracing/trace_pipe can get the output.

# bpftool prog load .output/kprobe.bpf.o /sys/fs/bpf/kprobe autoattach

But the bpftool perf list and bpftool link list are different from ./kprobe.

root@-VirtualBox:~# bpftool perf list
root@-VirtualBox:~# bpftool link list
42: perf_event  prog 1262

[qmonnet]

But the bpftool perf list and bpftool link list are different from ./kprobe.

I would expect ./kprobe to maybe attach your program “the old way”, without a BPF link; so the program would show in bpftool perf list, but not in bpftool link list. Conversely, I think bpftool uses BPF links, so your program shows in bpftool link but not in bpftool perf. The fact that there are two solutions is also an artefact of the historical BPF evolutions; the most recent (and flexible) approach would be with the BPF links, but this would not otherwise affect your program behaviour or performance. In other words, what you observe is expected, and shouldn't have any impact on your program.

As for how to unify the output from bpftool listings, I haven't figured out a satisfying solution yet :confused:.

[Songchunbo]

Got it. Thanks very much for the detail explanation.

Loading and attaching programs are two separate steps, although many user space tools usually handle both at the same time.

Now that BPF links exist, this requirement is no longer valid and we could attach programs with bpftool. But people don't usually need to attach programs that have been loaded from a previous bpftool invocation, and we just haven't implemented it so far. Last time someone wanted to load+attach they contributed the autoattach feature, which tells bpftool to do both steps at the same time, provided libbpf can derive the right attach point from the ELF section names; this should get you covered for your use case, I expect.