Re: bpf: Question about odd BPF verifier behaviour

[Matt Bobrowski <mattbobrowski@google.com>]

[-- Attachment #1: Type: text/plain, Size: 14233 bytes --]

Sorry Eduard, I replied late last night although the email bounced due
to exceeding the mail char limit. Let's try attaching a compressed
variant of the requested files, which includes the compiled kernel's
BTF and the kernel's config.

On Fri, Feb 24, 2023 at 04:14:44PM +0200, Eduard Zingerman wrote:
> On Fri, 2023-02-24 at 05:31 +0000, Matt Bobrowski wrote:
> [...]
> > > 
> > > 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?
> 
> This shouldn't really be the case, as pahole de-duplicates BTF
> definitions when BTF is added to vmlinux.
> 
> One scenario I can think of is when `linux_binprm` data structure
> comes from multiple modules but not from `vmlinux` itself. 
> However, the log would be a bit different in such case:
> 
>     libbpf: CO-RE relocating [107] struct bpf_testmod_struct_arg_2: found target candidate [90383] struct bpf_testmod_struct_arg_2 in [bpf_testmod]
>     libbpf: CO-RE relocating [107] struct bpf_testmod_struct_arg_2: found target candidate [90353] struct bpf_testmod_struct_arg_2 in [bpf_testmod1]
> 
> Note `in [bpf_testmod]` and `in [bpf_testmod1]` which are my test modules.
> In your log it says `in [vmlinux]`.
> 
> Which suggests that there are multiple _conflicting_ definitions of
> `linux_binprm` in your `vmlinux` and these definitions could not be
> de-duplicated. Could you please run the following command inside QEMU and
> share the output?

This sounds about right, as I'm also seeing the following during the
compilation phase of the kernel:

WARN: multiple IDs found for 'linux_binprm': 3971, 380629 - using 3971
WARN: multiple IDs found for 'task_struct': 214, 384262 - using 214
WARN: multiple IDs found for 'file': 454, 384289 - using 454
WARN: multiple IDs found for 'vm_area_struct': 459, 384292 - using 459
WARN: multiple IDs found for 'seq_file': 1069, 384326 - using 1069
WARN: multiple IDs found for 'inode': 711, 384439 - using 711
WARN: multiple IDs found for 'path': 743, 384468 - using 743
WARN: multiple IDs found for 'cgroup': 765, 384477 - using 765

I don't quite see understand why this would just start being a problem
now though? Perhaps this could be an issue with pahole? But then
again, you've also managed to build pahole from source and not run
into such issues...

>     bpftool btf dump file /sys/kernel/btf/vmlinux | grep "'linux_binprm'" -A 30
>     
> Or outside the VM:
> 
>     bpftool btf dump file {kernel}/vmlinux | grep "'linux_binprm'" -A 30
> 
> Also, could you please share full `.config`?

Sure, the output from both can be found within the attached archive.

> Do you use any non-standard compilation flags?

Not for the kernel, nor the BPF program.

Would it help if I also provided the raw compiled binary of the BPF
program?

> > > 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().
> 
> To be honest, it looks like something is off with BTF ids and `llist_node`
> gets randomly picked, but that's a speculation w/o hard evidence.

Yes, I agree, but I'm not 100% sure why this is happening
either. Through some rough debugging, I've literally observed the BPF
verifier passing 2 completely different BTF IDs to
btf_struct_ids_match(), but I also don't know whether this is expected
or not? :)

/M

[-- Attachment #2: kernel_config_btf_output.tar.gz --]
[-- Type: application/gzip, Size: 34129 bytes --]