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.
