Re: bpf: Question about odd BPF verifier behaviour

[Matt Bobrowski <mattbobrowski@google.com>]

On Thu, Feb 23, 2023 at 02:42:40PM +0200, Eduard Zingerman wrote:
> On Thu, 2023-02-23 at 09:37 +0000, Matt Bobrowski wrote:
> [...]
> > LMK whether you need any more information.
> > 
> > /M
> 
> Hi Matt,
> 
> Unfortunately I can't reproduce the issue.
> Here are the versions of the tools/repos that I use:
> 
> - kernel (tried both):
>   - https://github.com/torvalds/linux.git
>     a5c95ca18a98 ("Merge tag 'drm-next-2023-02-23' of git://anongit.freedesktop.org/drm/drm")
>   - https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git
>     830b3c68c1fb ("Linux 6.1")
> - config (tried both):
>   - one obtained using your instructions
>   - my small debug config for executing BPF tests ([1])
> - LLVM:
>   https://github.com/llvm/llvm-project.git
>   bc85cf168743 ("[TextAPI] Add support for TBDv5 Files to nm & tapi-diff")
> - pahole:
>   git@github.com:acmel/dwarves.git
>   ef68019 ("pahole: Update man page for options also")
> - libbpf-bootstrap (just followed your instructions):
>   https://github.com/libbpf/libbpf-bootstrap
>   db4f7ad ("cmake: Fix btf header missing in legacy kernel env.")
> - gcc (from my distro):
>   gcc version 11.3.0 (Ubuntu 11.3.0-1ubuntu1~22.04)
> - cat /etc/os-release 
>   NAME="Linux Mint"
>   VERSION="21.1 (Vera)"
>   ID=linuxmint
>   ID_LIKE="ubuntu debian"
>   PRETTY_NAME="Linux Mint 21.1"
>   VERSION_ID="21.1"
>   VERSION_CODENAME=vera
>   UBUNTU_CODENAME=jammy
> 
> Could you please copy-paste output of the `fentry` application, I'd
> like to see the log output of the libbpf while it processes
> relocations, e.g. here is what it prints for me:
> 
>     # /home/eddy/work/libbpf-bootstrap/examples/c/fentry
>     libbpf: loading object 'fentry_bpf' from buffer
>     libbpf: elf: section(3) lsm.s/bprm_committed_creds, size 136, link 0, flags 6, type=1
>     libbpf: sec 'lsm.s/bprm_committed_creds': found program 'dbg' at insn offset 0 (0 bytes), code size 17 insns (136 bytes)
>     libbpf: elf: section(4) license, size 13, link 0, flags 3, type=1
>     libbpf: license of fentry_bpf is Dual BSD/GPL
>     libbpf: elf: section(5) .BTF, size 5114, link 0, flags 0, type=1
>     libbpf: elf: section(7) .BTF.ext, size 188, link 0, flags 0, type=1
>     libbpf: elf: section(10) .symtab, size 96, link 1, flags 0, type=2
>     libbpf: looking for externs among 4 symbols...
>     libbpf: collected 0 externs total
>     libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
>     libbpf: sec 'lsm.s/bprm_committed_creds': found 1 CO-RE relocations
>     libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [7241] struct linux_binprm in [vmlinux]
>     libbpf: prog 'dbg': relo #0: <byte_off> [6] struct linux_binprm.file (0:11 @ offset 64)
>     libbpf: prog 'dbg': relo #0: matching candidate #0 <byte_off> [7241] struct linux_binprm.file (0:11 @ offset 64)
>     libbpf: prog 'dbg': relo #0: patched insn #10 (LDX/ST/STX) off 64 -> 64
>     Successfully started! Please run `sudo cat /sys/kernel/debug/tracing/trace_pipe` to see output of the BPF programs.

Sure, here it is:

# ./fentry
libbpf: loading object 'fentry_bpf' from buffer
libbpf: elf: section(3) lsm.s/bprm_committed_creds, size 136, link 0, flags 6, type=1
libbpf: sec 'lsm.s/bprm_committed_creds': found program 'dbg' at insn offset 0 (0 bytes), code size 17 insns (136 bytes)
libbpf: elf: section(4) license, size 13, link 0, flags 3, type=1
libbpf: license of fentry_bpf is Dual BSD/GPL
libbpf: elf: section(5) .BTF, size 5149, link 0, flags 0, type=1
libbpf: elf: section(7) .BTF.ext, size 188, link 0, flags 0, type=1
libbpf: elf: section(10) .symtab, size 96, link 1, flags 0, type=2
libbpf: looking for externs among 4 symbols...
libbpf: collected 0 externs total
libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
libbpf: sec 'lsm.s/bprm_committed_creds': found 1 CO-RE relocations
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [3971] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [9214] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [36310] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [36973] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [122219] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [151720] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [163602] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [175117] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [176645] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [179130] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [189263] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [237046] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [240978] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [264207] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [268773] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [276058] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [295158] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [306160] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [347067] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [349932] struct linux_binprm in [vmlinux]
libbpf: CO-RE relocating [6] struct linux_binprm: found target candidate [380629] struct linux_binprm in [vmlinux]
libbpf: prog 'dbg': relo #0: <byte_off> [6] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #0 <byte_off> [3971] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #1 <byte_off> [9214] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #2 <byte_off> [36310] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #3 <byte_off> [36973] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #4 <byte_off> [122219] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #5 <byte_off> [151720] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #6 <byte_off> [163602] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #7 <byte_off> [175117] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #8 <byte_off> [176645] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #9 <byte_off> [179130] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #10 <byte_off> [189263] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #11 <byte_off> [237046] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #12 <byte_off> [240978] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #13 <byte_off> [264207] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #14 <byte_off> [268773] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #15 <byte_off> [276058] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #16 <byte_off> [295158] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #17 <byte_off> [306160] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #18 <byte_off> [347067] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #19 <byte_off> [349932] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: matching candidate #20 <byte_off> [380629] struct linux_binprm.file (0:11 @ offset 64)
libbpf: prog 'dbg': relo #0: patched insn #10 (LDX/ST/STX) off 64 -> 64
libbpf: prog 'dbg': BPF program load failed: Permission denied
libbpf: prog 'dbg': -- BEGIN PROG LOAD LOG --
reg type unsupported for arg#0 function dbg#5
0: R1=ctx(off=0,imm=0) R10=fp0
; int BPF_PROG(dbg, struct linux_binprm *bprm)
0: (79) r1 = *(u64 *)(r1 +0)
func 'bpf_lsm_bprm_committed_creds' arg0 has btf_id 176645 type STRUCT 'linux_binprm'
1: R1_w=trusted_ptr_linux_binprm(off=0,imm=0)
1: (b7) r2 = 0                        ; R2_w=0
; char buf[64] = {0};
2: (7b) *(u64 *)(r10 -8) = r2         ; R2_w=0 R10=fp0 fp-8_w=00000000
3: (7b) *(u64 *)(r10 -16) = r2        ; R2_w=0 R10=fp0 fp-16_w=00000000
4: (7b) *(u64 *)(r10 -24) = r2        ; R2_w=0 R10=fp0 fp-24_w=00000000
5: (7b) *(u64 *)(r10 -32) = r2        ; R2_w=0 R10=fp0 fp-32_w=00000000
6: (7b) *(u64 *)(r10 -40) = r2        ; R2_w=0 R10=fp0 fp-40_w=00000000
7: (7b) *(u64 *)(r10 -48) = r2        ; R2_w=0 R10=fp0 fp-48_w=00000000
8: (7b) *(u64 *)(r10 -56) = r2        ; R2_w=0 R10=fp0 fp-56_w=00000000
9: (7b) *(u64 *)(r10 -64) = r2        ; R2_w=0 R10=fp0 fp-64_w=00000000
; bpf_ima_file_hash(bprm->file, buf, sizeof(buf));
10: (79) r1 = *(u64 *)(r1 +64)        ; R1_w=ptr_file(off=0,imm=0)
11: (bf) r2 = r10                     ; R2_w=fp0 R10=fp0
; 
12: (07) r2 += -64                    ; R2_w=fp-64
; bpf_ima_file_hash(bprm->file, buf, sizeof(buf));
13: (b7) r3 = 64                      ; R3_w=64
14: (85) call bpf_ima_file_hash#193
cannot access ptr member next with moff 0 in struct llist_node with off 0 size 1
R1 is of type file but file is expected
processed 15 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
-- END PROG LOAD LOG --
libbpf: prog 'dbg': failed to load: -13
libbpf: failed to load object 'fentry_bpf'
libbpf: failed to load BPF skeleton 'fentry_bpf': -13
Failed to open BPF skeleton

It looks like there are a lot more relocations attempted by libbpf,
but I suspect that's a result of their being multiple definitions of
that same struct within the running kernel's BTF?

> Also, could you please compile `veristat` tool as below:
> 
>     cd ${kernel}/tools/testing/selftests/bpf
>     make -j16 veristat
> 
> And post the output of the following command (from within QEMU):
> 
>     ./veristat -l7 -v ${path-to-libbpf-bootstrap-within-vm}/examples/c/.output/fentry.bpf.o
> 
> It should produce the verification log as an output.
> 
> The reason I'm asking is that your verification log looks kinda strange:
> 
> >    ; bpf_ima_file_hash(bprm->file, buf, 64);
> >    13: (b7) r3 = 64                      ; R3_w=64
> >    14: (85) call bpf_ima_file_hash#193
> >    cannot access ptr member next with moff 0 in struct llist_node with off 0 size 1
> >    R1 is of type file but file is expected
> >    processed 15 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
> 
> I don't understand why it mentions `struct llist_node` here and don't
> have such messages in my log ([2]).

Yes, I also found this strange and couldn't find a valid explanation
for it either. Looking at the BPF verifier code in the kernel, we hit
this case when performing the struct member walk in btf_struct_walk().

Here is the output from the veristat utility:

./veristat -l7 -v ./fentry.bpf.o 
Processing 'fentry.bpf.o'...
libbpf: prog 'dbg': BPF program load failed: Permission denied
libbpf: prog 'dbg': failed to load: -13
libbpf: failed to load object './fentry.bpf.o'
PROCESSING ./fentry.bpf.o/dbg, DURATION US: 4903, VERDICT: failure, VERIFIER LOG:
func#0 @0
reg type unsupported for arg#0 function dbg#5
0: R1=ctx(off=0,imm=0) R10=fp0
; int BPF_PROG(dbg, struct linux_binprm *bprm)
0: (79) r1 = *(u64 *)(r1 +0)
func 'bpf_lsm_bprm_committed_creds' arg0 has btf_id 176645 type STRUCT 'linux_binprm'
1: R1_w=trusted_ptr_linux_binprm(off=0,imm=0)
1: (b7) r2 = 0                        ; R2_w=0
; char buf[64] = {0};
2: (7b) *(u64 *)(r10 -8) = r2
last_idx 2 first_idx 0
regs=4 stack=0 before 1: (b7) r2 = 0
3: R2_w=0 R10=fp0 fp-8_w=00000000
3: (7b) *(u64 *)(r10 -16) = r2
last_idx 3 first_idx 0
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
4: R2_w=0 R10=fp0 fp-16_w=00000000
4: (7b) *(u64 *)(r10 -24) = r2
last_idx 4 first_idx 0
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
5: R2_w=0 R10=fp0 fp-24_w=00000000
5: (7b) *(u64 *)(r10 -32) = r2
last_idx 5 first_idx 0
regs=4 stack=0 before 4: (7b) *(u64 *)(r10 -24) = r2
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
6: R2_w=0 R10=fp0 fp-32_w=00000000
6: (7b) *(u64 *)(r10 -40) = r2
last_idx 6 first_idx 0
regs=4 stack=0 before 5: (7b) *(u64 *)(r10 -32) = r2
regs=4 stack=0 before 4: (7b) *(u64 *)(r10 -24) = r2
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
7: R2_w=0 R10=fp0 fp-40_w=00000000
7: (7b) *(u64 *)(r10 -48) = r2
last_idx 7 first_idx 0
regs=4 stack=0 before 6: (7b) *(u64 *)(r10 -40) = r2
regs=4 stack=0 before 5: (7b) *(u64 *)(r10 -32) = r2
regs=4 stack=0 before 4: (7b) *(u64 *)(r10 -24) = r2
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
8: R2_w=0 R10=fp0 fp-48_w=00000000
8: (7b) *(u64 *)(r10 -56) = r2
last_idx 8 first_idx 0
regs=4 stack=0 before 7: (7b) *(u64 *)(r10 -48) = r2
regs=4 stack=0 before 6: (7b) *(u64 *)(r10 -40) = r2
regs=4 stack=0 before 5: (7b) *(u64 *)(r10 -32) = r2
regs=4 stack=0 before 4: (7b) *(u64 *)(r10 -24) = r2
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
9: R2_w=0 R10=fp0 fp-56_w=00000000
9: (7b) *(u64 *)(r10 -64) = r2
last_idx 9 first_idx 0
regs=4 stack=0 before 8: (7b) *(u64 *)(r10 -56) = r2
regs=4 stack=0 before 7: (7b) *(u64 *)(r10 -48) = r2
regs=4 stack=0 before 6: (7b) *(u64 *)(r10 -40) = r2
regs=4 stack=0 before 5: (7b) *(u64 *)(r10 -32) = r2
regs=4 stack=0 before 4: (7b) *(u64 *)(r10 -24) = r2
regs=4 stack=0 before 3: (7b) *(u64 *)(r10 -16) = r2
regs=4 stack=0 before 2: (7b) *(u64 *)(r10 -8) = r2
regs=4 stack=0 before 1: (b7) r2 = 0
10: R2_w=0 R10=fp0 fp-64_w=00000000
; bpf_ima_file_hash(bprm->file, buf, sizeof(buf));
10: (79) r1 = *(u64 *)(r1 +64)        ; R1_w=ptr_file(off=0,imm=0)
11: (bf) r2 = r10                     ; R2_w=fp0 R10=fp0
; 
12: (07) r2 += -64                    ; R2_w=fp-64
; bpf_ima_file_hash(bprm->file, buf, sizeof(buf));
13: (b7) r3 = 64                      ; R3_w=64
14: (85) call bpf_ima_file_hash#193
cannot access ptr member next with moff 0 in struct llist_node with off 0 size 1
R1 is of type file but file is expected
verification time 4903 usec
stack depth 64
processed 15 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0

File          Program  Verdict  Duration (us)  Insns  States  Peak states
------------  -------  -------  -------------  -----  ------  -----------
fentry.bpf.o  dbg      failure           4903     15       0            0
------------  -------  -------  -------------  -----  ------  -----------
Done. Processed 1 files, 0 programs. Skipped 1 files, 0 programs.

> [1] My config for BPF testing
>     https://gist.github.com/eddyz87/aca79692d7bf57cfdd01b283b4304fd8
> [2] Veristat verification log
>     https://gist.github.com/eddyz87/49b211740bf99c426a37a3555b4542a3

/M