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?
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`?
Do you use any non-standard compilation flags?
>
> > 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.
Thanks,
Eduard
