Re: -EBUSY with some selftests on 5.7-rcX

Mikko Ylinen <mikko.ylinen@xxxxxxxxxxxxxxx> · Wed, 6 May 2020 22:28:51 +0300

Hi,

On 01/05/2020 23:18, Andrii Nakryiko wrote:
On Tue, Apr 28, 2020 at 3:33 AM Mikko Ylinen
<mikko.ylinen@xxxxxxxxxxxxxxx> wrote:

Hi,

I'm testing BPF LSM and wanted to verify my setup by running the
test_lsm selftests (./test_progs -vv -t test_lsm) but it fails:

libbpf: loading object 'lsm' from buffer
libbpf: section(1) .strtab, size 306, link 0, flags 0, type=3
libbpf: skip section(1) .strtab
libbpf: section(2) .text, size 0, link 0, flags 6, type=1
libbpf: skip section(2) .text
libbpf: section(3) lsm/file_mprotect, size 192, link 0, flags 6, type=1
libbpf: found program lsm/file_mprotect
libbpf: section(4) .rellsm/file_mprotect, size 32, link 25, flags 0, type=9
libbpf: section(5) lsm/bprm_committed_creds, size 104, link 0, flags 6,
type=1
libbpf: found program lsm/bprm_committed_creds
libbpf: section(6) .rellsm/bprm_committed_creds, size 32, link 25, flags
0, type=9
libbpf: section(7) license, size 4, link 0, flags 3, type=1
libbpf: license of lsm is GPL
libbpf: section(8) .bss, size 12, link 0, flags 3, type=8
libbpf: section(9) .debug_str, size 133448, link 0, flags 30, type=1
libbpf: skip section(9) .debug_str
libbpf: section(10) .debug_loc, size 428, link 0, flags 0, type=1
libbpf: skip section(10) .debug_loc
libbpf: section(11) .rel.debug_loc, size 112, link 25, flags 0, type=9
libbpf: skip relo .rel.debug_loc(11) for section(10)
libbpf: section(12) .debug_abbrev, size 901, link 0, flags 0, type=1
libbpf: skip section(12) .debug_abbrev
libbpf: section(13) .debug_info, size 223699, link 0, flags 0, type=1
libbpf: skip section(13) .debug_info
libbpf: section(14) .rel.debug_info, size 112, link 25, flags 0, type=9
libbpf: skip relo .rel.debug_info(14) for section(13)
libbpf: section(15) .debug_ranges, size 96, link 0, flags 0, type=1
libbpf: skip section(15) .debug_ranges
libbpf: section(16) .rel.debug_ranges, size 128, link 25, flags 0, type=9
libbpf: skip relo .rel.debug_ranges(16) for section(15)
libbpf: section(17) .BTF, size 5421, link 0, flags 0, type=1
libbpf: section(18) .rel.BTF, size 64, link 25, flags 0, type=9
libbpf: skip relo .rel.BTF(18) for section(17)
libbpf: section(19) .BTF.ext, size 484, link 0, flags 0, type=1
libbpf: section(20) .rel.BTF.ext, size 416, link 25, flags 0, type=9
libbpf: skip relo .rel.BTF.ext(20) for section(19)
libbpf: section(21) .debug_frame, size 64, link 0, flags 0, type=1
libbpf: skip section(21) .debug_frame
libbpf: section(22) .rel.debug_frame, size 32, link 25, flags 0, type=9
libbpf: skip relo .rel.debug_frame(22) for section(21)
libbpf: section(23) .debug_line, size 227, link 0, flags 0, type=1
libbpf: skip section(23) .debug_line
libbpf: section(24) .rel.debug_line, size 32, link 25, flags 0, type=9
libbpf: skip relo .rel.debug_line(24) for section(23)
libbpf: section(25) .symtab, size 288, link 1, flags 0, type=2
libbpf: looking for externs among 12 symbols...
libbpf: collected 0 externs total
libbpf: map 'lsm.bss' (global data): at sec_idx 8, offset 0, flags 400.
libbpf: map 0 is "lsm.bss"
libbpf: collecting relocating info for: 'lsm/file_mprotect'
libbpf: relo for shdr 8, symb 8, value 0, type 1, bind 1, name 232
('monitored_pid'), insn 12
libbpf: found data map 0 (lsm.bss, sec 8, off 0) for insn 12
libbpf: relo for shdr 8, symb 9, value 4, type 1, bind 1, name 34
('mprotect_count'), insn 17
libbpf: found data map 0 (lsm.bss, sec 8, off 0) for insn 17
libbpf: collecting relocating info for: 'lsm/bprm_committed_creds'
libbpf: relo for shdr 8, symb 8, value 0, type 1, bind 1, name 232
('monitored_pid'), insn 1
libbpf: found data map 0 (lsm.bss, sec 8, off 0) for insn 1
libbpf: relo for shdr 8, symb 7, value 8, type 1, bind 1, name 49
('bprm_count'), insn 6
libbpf: found data map 0 (lsm.bss, sec 8, off 0) for insn 6
libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
libbpf: created map lsm.bss: fd=4
libbpf: loading kernel BTF '/sys/kernel/btf/vmlinux': 0
libbpf: prog 'lsm/file_mprotect': performing 4 CO-RE offset relocs
libbpf: prog 'lsm/file_mprotect': relo #0: kind 0, spec is [6]
vm_area_struct + 0:6 => 64.0 @ &x[0].vm_mm
libbpf: [6] vm_area_struct: found candidate [465] vm_area_struct
libbpf: prog 'lsm/file_mprotect': relo #0: matching candidate #0
vm_area_struct against spec [465] vm_area_struct + 0:6 => 64.0 @
&x[0].vm_mm: 1
libbpf: prog 'lsm/file_mprotect': relo #0: patched insn #5 (LDX/ST/STX)
off 64 -> 64
libbpf: prog 'lsm/file_mprotect': relo #1: kind 0, spec is [31]
mm_struct + 0:0:35 => 304.0 @ &x[0].start_stack
libbpf: [31] mm_struct: found candidate [260] mm_struct
libbpf: prog 'lsm/file_mprotect': relo #1: matching candidate #0
mm_struct against spec [260] mm_struct + 0:0:35 => 304.0 @
&x[0].start_stack: 1
libbpf: prog 'lsm/file_mprotect': relo #1: patched insn #7 (LDX/ST/STX)
off 304 -> 304
libbpf: prog 'lsm/file_mprotect': relo #2: kind 0, spec is [6]
vm_area_struct + 0:0 => 0.0 @ &x[0].vm_start
libbpf: prog 'lsm/file_mprotect': relo #2: matching candidate #0
vm_area_struct against spec [465] vm_area_struct + 0:0 => 0.0 @
&x[0].vm_start: 1
libbpf: prog 'lsm/file_mprotect': relo #2: patched insn #8 (LDX/ST/STX)
off 0 -> 0
libbpf: prog 'lsm/file_mprotect': relo #3: kind 0, spec is [6]
vm_area_struct + 0:1 => 8.0 @ &x[0].vm_end
libbpf: prog 'lsm/file_mprotect': relo #3: matching candidate #0
vm_area_struct against spec [465] vm_area_struct + 0:1 => 8.0 @
&x[0].vm_end: 1
libbpf: prog 'lsm/file_mprotect': relo #3: patched insn #10 (LDX/ST/STX)
off 8 -> 8
test_test_lsm:PASS:skel_load 0 nsec
libbpf: program 'lsm/file_mprotect': failed to attach: Device or
resource busy
libbpf: failed to auto-attach program 'test_int_hook': -16
test_test_lsm:FAIL:attach lsm attach failed: -16
#70 test_lsm:FAIL
Summary: 0/0 PASSED, 0 SKIPPED, 1 FAILED

I get -EBUSY with fentry_fexit test too:

-EBUSY in fentry/fexit kernel code most probably means that there is
either extension program (freplace) installed for that target program
or that same program is already attached through previous fentry/fexit
attachment. See code in bpf_trampoline_link_prog(). If you can, can
you please add a bunch of printk() statements in corresponding error
handling code paths to figure out which one it is?

The error seems to come from register_fentry() but I don't yet have
good logs what goes wrong.

Also, I wonder if this happens right after you restart your kernel/OS?
Is it happening deterministically or just from time to time?

I haven't seen a PASS at all yet. I run the tests right after booting 
the VM.

# ./test_progs -t fentry_fexit
test_fentry_fexit:PASS:fentry_skel_load 0 nsec
test_fentry_fexit:PASS:fexit_skel_load 0 nsec
libbpf: program 'fentry/bpf_fentry_test1': failed to attach: Device or
resource busy
libbpf: failed to auto-attach program 'test1': -16
test_fentry_fexit:FAIL:fentry_attach fentry attach failed: -16
#13 fentry_fexit:FAIL
Summary: 0/0 PASSED, 0 SKIPPED, 1 FAILED

However, btf_dump is OK:

# ./test_progs -t btf_dump
#5/1 btf_dump: syntax:OK
#5/2 btf_dump: ordering:OK
#5/3 btf_dump: padding:OK
#5/4 btf_dump: packing:OK
#5/5 btf_dump: bitfields:OK
#5/6 btf_dump: multidim:OK
#5/7 btf_dump: namespacing:OK
#5 btf_dump:OK
Summary: 1/7 PASSED, 0 SKIPPED, 0 FAILED

btf_dump is completely irrelevant test here, it tests libbpf's BTF
dumping capabilities and doesn't touch anything in kernel, so this
doesn't give any extra hint, unfortunately.

Any feedback what to check? I don't have any other tests
running in parallel.

After this test fails, run `sudo bpftool prog show` and `sudo bpftool
link show`, see if there is anything suspicious. bpftool link show is
available with latest master in bpf-next tree, so you'd have to
rebuild your kernel. If nothing catches your eye and helps resolve
this, please post output here as well.

I applied the 'bpf_link observability API' series. bpftool link show
prints nothing.

# clang --version
clang version 10.0.0
Target: x86_64-generic-linux
Thread model: posix
InstalledDir: /usr/bin
# pahole --version
v1.16

5.7-rc3

-- Regards, Mikko