Re: "bpf: Improve the info.func_info and info.func_info_rec_size behavior" breaks strace self tests

[Martin Lau]

On Thu, Jan 03, 2019 at 11:41:18PM +0100, Heiko Carstens wrote:
> On Thu, Jan 03, 2019 at 07:12:05PM +0000, Martin Lau wrote:
> > On Thu, Jan 03, 2019 at 12:46:13PM +0100, Heiko Carstens wrote:
> > > Hello,
> > > 
> > > the kernel commit 7337224fc150 ("bpf: Improve the info.func_info and
> > > info.func_info_rec_size behavior") breaks one of strace's self tests:
> > > 
> > > FAIL: bpf-obj_get_info_by_fd-prog-v.gen
> > The strace's bpf-obj_get_info_by_fd-prog-v test did fail.  However,
> > I failed to see how 7337224fc150 broke it.  How do you trace down to
> > commit 7337224fc150 and can you share your test output?
> > 
> > The failure I can reproduce is EFAULT.  It should have been failing
> > as early as "nr_jited_ksyms" is added to "struct bpf_prog_info"
> > in linux/bpf.h.
> 
> Ah, sorry(!), I forgot to mention an important detail: the test
> failure happens only if executed as normal (non-root) user.
> 
> With 7337224fc150 ("bpf: Improve the info.func_info and
> info.func_info_rec_size behavior") the failure happens. With commit
> 30da46b5dc3a ("tools: bpftool: add a command to dump the trace pipe")
> it passes; which is one commit earlier.
> 
> FAIL: bpf-obj_get_info_by_fd-prog-v.gen
> =======================================
> 
> --- exp	2019-01-03 23:31:49.576949303 +0100
> +++ log	2019-01-03 23:31:49.576949303 +0100
> @@ -1,8 +1,8 @@
>  bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=8, max_entries=1, map_flags=0, inner_map_fd=0</dev/null>, map_name="test_map", map_ifindex=0}, 48) = 3<anon_inode:bpf-map>
>  bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=9, insns=[{code=BPF_ALU64|BPF_K|BPF_MOV, dst_reg=BPF_REG_1, src_reg=BPF_REG_0, off=0, imm=0}, {code=BPF_STX|BPF_W|BPF_MEM, dst_reg=BPF_REG_10, src_reg=BPF_REG_1, off=-4, imm=0}, {code=BPF_ALU64|BPF_X|BPF_MOV, dst_reg=BPF_REG_2, src_reg=BPF_REG_10, off=0, imm=0}, {code=BPF_ALU64|BPF_K|BPF_ADD, dst_reg=BPF_REG_2, src_reg=BPF_REG_0, off=0, imm=0xfffffffc}, {code=BPF_LD|BPF_DW|BPF_IMM, dst_reg=BPF_REG_1, src_reg=BPF_REG_1, off=0, imm=0x3}, {code=BPF_LD|BPF_W|BPF_IMM, dst_reg=BPF_REG_0, src_reg=BPF_REG_0, off=0, imm=0}, {code=BPF_JMP|BPF_K|BPF_CALL, dst_reg=BPF_REG_0, src_reg=BPF_REG_0, off=0, imm=0x1}, {code=BPF_ALU64|BPF_K|BPF_MOV, dst_reg=BPF_REG_0, src_reg=BPF_REG_0, off=0, imm=0}, {code=BPF_JMP|BPF_K|BPF_EXIT, dst_reg=BPF_REG_0, src_reg=BPF_REG_0, off=0, imm=0}], license="BSD", log_level=42, log_size=4096, log_buf="", kern_version=KERNEL_VERSION(57005, 192, 222), prog_flags=0, prog_name="test_prog", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 72) = 4<anon_inode:bpf-prog>
>  bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=3<anon_inode:bpf-map>, info_len=128 => 80, info={type=BPF_MAP_TYPE_ARRAY, id=15, key_size=4, value_size=8, max_entries=1, map_flags=0, name="test_map", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
> -bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168 => 152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=NULL, load_time=28281352029, created_by_uid=1000, nr_map_ids=0 => 1, map_ids=NULL, name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
> -bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=336, xlated_prog_insns=0x3ff8d6f7000, load_time=28281352029, created_by_uid=1000, nr_map_ids=2, map_ids=0x3ff8d6f1000, name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = -1 EFAULT (Bad address)
> -bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=[], load_time=28281352029, created_by_uid=1000, nr_map_ids=0 => 1, map_ids=[], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
> -bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=[], load_time=28281352029, created_by_uid=1000, nr_map_ids=2 => 1, map_ids=[15], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
> +bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168 => 152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=NULL, load_time=28281352029, created_by_uid=1000, nr_map_ids=0 => 1, map_ids=NULL, name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..151 */ "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = 0
> +bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=336, xlated_prog_insns=0x3ff8d6f7000, load_time=28281352029, created_by_uid=1000, nr_map_ids=2, map_ids=0x3ff8d6f1000, name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..151 */ "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = -1 EFAULT (Bad address)
> +bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=[], load_time=28281352029, created_by_uid=1000, nr_map_ids=0 => 1, map_ids=[], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..151 */ "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = 0
> +bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=152, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=8, tag="\xde\x90\x83\x18\xfb\x16\xd8\x9c", jited_prog_len=0, jited_prog_insns=NULL, xlated_prog_len=0, xlated_prog_insns=[], load_time=28281352029, created_by_uid=1000, nr_map_ids=2 => 1, map_ids=[15], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..151 */ "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = 0
>  +++ exited with 0 +++
> bpf-obj_get_info_by_fd-prog-v.gen.test: failed test: ../../strace -a20 -y -v -e trace=bpf ../bpf-obj_get_info_by_fd-prog-v output mismatch
> FAIL bpf-obj_get_info_by_fd-prog-v.gen.test (exit status: 1)
>
I am running against linux-next.  I don't see how root and non-root affect
thing here.  I guess the test has been running without jit so far?

1) root or not, if jit is enabled,
   without the memset() fix in the bpf-obj_get_info_by_fd.c in my last email,
   they all failed:
   [root@arch-fb-vm1 tests]# ./bpf-obj_get_info_by_fd-prog-v.gen.test
   BPF_OBJ_GET_INFO_BY_FD prog 2 failed: Bad address
   bpf-obj_get_info_by_fd-prog-v.gen.test: skipped test: ../bpf-obj_get_info_by_fd-prog-v exited with code 77

   Please fix this first.

2) After having the memset fix:
   Root or not, for jited program, if I run
   ./bpf-obj_get_info_by_fd-prog-v.gen.test, they failed.  If I read the
   init.sh correclty, it fails because there is a diff between the
   ./bpf-obj_get_info_by_fd-prog-v stdout and the "strace -o log".  I think
   "strace -o log" only has the /* bytes 104..151 */ part if some bytes
   are non-zero?

   Regardless, the test program "bpf-obj_get_info_by_fd.c" is telling
   the kernel that the userspace "info" is in size 168 bytes.
   The kernel then tells as much details as possible about
   a bpf prog in "info".  I don't see a ABI breakage here.

   I believe the test just happens to work so far because it has been running
   without jit?

   If I run it with jit enabled:
-bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=35, tag="\xda\xbf\x02\x07\xd1\x99\x24\x86", jited_prog_len=0 => 110, jited_prog_insns=NULL, xlated_prog_len=0 => 120, xlated_prog_insns=[], load_time=2476906063975, created_by_uid=0, nr_map_ids=0 => 1, map_ids=[], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
-bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=35, tag="\xda\xbf\x02\x07\xd1\x99\x24\x86", jited_prog_len=0 => 110, jited_prog_insns=NULL, xlated_prog_len=0 => 120, xlated_prog_insns=[], load_time=2476906063975, created_by_uid=0, nr_map_ids=2 => 1, map_ids=[36], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0}}}, 16) = 0
+bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=35, tag="\xda\xbf\x02\x07\xd1\x99\x24\x86", jited_prog_len=0 => 110, jited_prog_insns=NULL, xlated_prog_len=0 => 120, xlated_prog_insns=[], load_time=2476906063975, created_by_uid=0, nr_map_ids=0 => 1, map_ids=[], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..167 */ "\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = 0
+bpf(BPF_OBJ_GET_INFO_BY_FD, {info={bpf_fd=4<anon_inode:bpf-prog>, info_len=168, info={type=BPF_PROG_TYPE_SOCKET_FILTER, id=35, tag="\xda\xbf\x02\x07\xd1\x99\x24\x86", jited_prog_len=0 => 110, jited_prog_insns=NULL, xlated_prog_len=0 => 120, xlated_prog_insns=[], load_time=2476906063975, created_by_uid=0, nr_map_ids=2 => 1, map_ids=[36], name="test_prog", ifindex=0, netns_dev=makedev(0, 0), netns_ino=0, /* bytes 104..167 */ "\x01\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00"}}}, 16) = 0

  The diff comes in as early as byte 104-th which is the nr_jited_ksyms == 1.

  Please fix the test program.  A protential fix is in bpf-obj_get_info_by_fd.c
  to printf the non-zero "/* bytes 104..1xx */..." the same way as the
  "strace -o log" does.