As BPF applications grow in size and complexity and are separated into multiple .bpf.c files that are statically linked together, it becomes harder and harder to match verifier's BPF assembly level output to original C code. While often annotated C source code is unique enough to be able to identify the file it belongs to, quite often this is actually problematic as parts of source code can be quite generic. Long story short, it is very useful to see source code file name and line number information along with the original C code. Verifier already knows this information, we just need to output it. This patch extends verifier log with file name and line number information, emitted next to original (presumably C) source code, annotating BPF assembly output, like so: ; <original C code> @ <filename>.bpf.c:<line> If file name has directory names in it, they are stripped away. This should be fine in practice as file names tend to be pretty unique with C code anyways, and keeping log size smaller is always good. In practice this might look something like below, where some code is coming from application files, while others are from libbpf's usdt.bpf.h header file: ; if (STROBEMETA_READ( @ strobemeta_probe.bpf.c:534 5592: (79) r1 = *(u64 *)(r10 -56) ; R1_w=mem_or_null(id=1589,sz=7680) R10=fp0 5593: (7b) *(u64 *)(r10 -56) = r1 ; R1_w=mem_or_null(id=1589,sz=7680) R10=fp0 5594: (79) r3 = *(u64 *)(r10 -8) ; R3_w=scalar() R10=fp0 fp-8=mmmmmmmm ... 170: (71) r1 = *(u8 *)(r8 +15) ; frame1: R1_w=scalar(...) R8_w=map_value(map=__bpf_usdt_spec,ks=4,vs=208) 171: (67) r1 <<= 56 ; frame1: R1_w=scalar(...) 172: (c7) r1 s>>= 56 ; frame1: R1_w=scalar(smin=smin32=-128,smax=smax32=127) ; val <<= arg_spec->arg_bitshift; @ usdt.bpf.h:183 173: (67) r1 <<= 32 ; frame1: R1_w=scalar(...) 174: (77) r1 >>= 32 ; frame1: R1_w=scalar(smin=0,smax=umax=0xffffffff,var_off=(0x0; 0xffffffff)) 175: (79) r2 = *(u64 *)(r10 -8) ; frame1: R2_w=scalar() R10=fp0 fp-8=mmmmmmmm 176: (6f) r2 <<= r1 ; frame1: R1_w=scalar(smin=0,smax=umax=0xffffffff,var_off=(0x0; 0xffffffff)) R2_w=scalar() 177: (7b) *(u64 *)(r10 -8) = r2 ; frame1: R2_w=scalar(id=61) R10=fp0 fp-8_w=scalar(id=61) ; if (arg_spec->arg_signed) @ usdt.bpf.h:184 178: (bf) r3 = r2 ; frame1: R2_w=scalar(id=61) R3_w=scalar(id=61) 179: (7f) r3 >>= r1 ; frame1: R1_w=scalar(smin=0,smax=umax=0xffffffff,var_off=(0x0; 0xffffffff)) R3_w=scalar() ; if (arg_spec->arg_signed) @ usdt.bpf.h:184 180: (71) r4 = *(u8 *)(r8 +14) 181: safe log_fixup tests needed a minor adjustment as verifier log output increased a bit and that test is quite sensitive to such changes. Signed-off-by: Andrii Nakryiko <andrii@kernel.org> Link: https://lore.kernel.org/r/20240212235944.2816107-1-andrii@kernel.org Signed-off-by: Alexei Starovoitov <ast@kernel.org>
181 lines
5.2 KiB
C
181 lines
5.2 KiB
C
// SPDX-License-Identifier: GPL-2.0
|
|
/* Copyright (c) 2022 Meta Platforms, Inc. and affiliates. */
|
|
#include <test_progs.h>
|
|
#include <bpf/btf.h>
|
|
|
|
#include "test_log_fixup.skel.h"
|
|
|
|
enum trunc_type {
|
|
TRUNC_NONE,
|
|
TRUNC_PARTIAL,
|
|
TRUNC_FULL,
|
|
};
|
|
|
|
static void bad_core_relo(size_t log_buf_size, enum trunc_type trunc_type)
|
|
{
|
|
char log_buf[8 * 1024];
|
|
struct test_log_fixup* skel;
|
|
int err;
|
|
|
|
skel = test_log_fixup__open();
|
|
if (!ASSERT_OK_PTR(skel, "skel_open"))
|
|
return;
|
|
|
|
bpf_program__set_autoload(skel->progs.bad_relo, true);
|
|
memset(log_buf, 0, sizeof(log_buf));
|
|
bpf_program__set_log_buf(skel->progs.bad_relo, log_buf, log_buf_size ?: sizeof(log_buf));
|
|
bpf_program__set_log_level(skel->progs.bad_relo, 1 | 8); /* BPF_LOG_FIXED to force truncation */
|
|
|
|
err = test_log_fixup__load(skel);
|
|
if (!ASSERT_ERR(err, "load_fail"))
|
|
goto cleanup;
|
|
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"0: <invalid CO-RE relocation>\n"
|
|
"failed to resolve CO-RE relocation <byte_sz> ",
|
|
"log_buf_part1");
|
|
|
|
switch (trunc_type) {
|
|
case TRUNC_NONE:
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"struct task_struct___bad.fake_field (0:1 @ offset 4)\n",
|
|
"log_buf_part2");
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0\n",
|
|
"log_buf_end");
|
|
break;
|
|
case TRUNC_PARTIAL:
|
|
/* we should get full libbpf message patch */
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"struct task_struct___bad.fake_field (0:1 @ offset 4)\n",
|
|
"log_buf_part2");
|
|
/* we shouldn't get full end of BPF verifier log */
|
|
ASSERT_NULL(strstr(log_buf, "max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0\n"),
|
|
"log_buf_end");
|
|
break;
|
|
case TRUNC_FULL:
|
|
/* we shouldn't get second part of libbpf message patch */
|
|
ASSERT_NULL(strstr(log_buf, "struct task_struct___bad.fake_field (0:1 @ offset 4)\n"),
|
|
"log_buf_part2");
|
|
/* we shouldn't get full end of BPF verifier log */
|
|
ASSERT_NULL(strstr(log_buf, "max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0\n"),
|
|
"log_buf_end");
|
|
break;
|
|
}
|
|
|
|
if (env.verbosity > VERBOSE_NONE)
|
|
printf("LOG: \n=================\n%s=================\n", log_buf);
|
|
cleanup:
|
|
test_log_fixup__destroy(skel);
|
|
}
|
|
|
|
static void bad_core_relo_subprog(void)
|
|
{
|
|
char log_buf[8 * 1024];
|
|
struct test_log_fixup* skel;
|
|
int err;
|
|
|
|
skel = test_log_fixup__open();
|
|
if (!ASSERT_OK_PTR(skel, "skel_open"))
|
|
return;
|
|
|
|
bpf_program__set_autoload(skel->progs.bad_relo_subprog, true);
|
|
bpf_program__set_log_buf(skel->progs.bad_relo_subprog, log_buf, sizeof(log_buf));
|
|
|
|
err = test_log_fixup__load(skel);
|
|
if (!ASSERT_ERR(err, "load_fail"))
|
|
goto cleanup;
|
|
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
": <invalid CO-RE relocation>\n"
|
|
"failed to resolve CO-RE relocation <byte_off> ",
|
|
"log_buf");
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"struct task_struct___bad.fake_field_subprog (0:2 @ offset 8)\n",
|
|
"log_buf");
|
|
|
|
if (env.verbosity > VERBOSE_NONE)
|
|
printf("LOG: \n=================\n%s=================\n", log_buf);
|
|
|
|
cleanup:
|
|
test_log_fixup__destroy(skel);
|
|
}
|
|
|
|
static void missing_map(void)
|
|
{
|
|
char log_buf[8 * 1024];
|
|
struct test_log_fixup* skel;
|
|
int err;
|
|
|
|
skel = test_log_fixup__open();
|
|
if (!ASSERT_OK_PTR(skel, "skel_open"))
|
|
return;
|
|
|
|
bpf_map__set_autocreate(skel->maps.missing_map, false);
|
|
|
|
bpf_program__set_autoload(skel->progs.use_missing_map, true);
|
|
bpf_program__set_log_buf(skel->progs.use_missing_map, log_buf, sizeof(log_buf));
|
|
|
|
err = test_log_fixup__load(skel);
|
|
if (!ASSERT_ERR(err, "load_fail"))
|
|
goto cleanup;
|
|
|
|
ASSERT_TRUE(bpf_map__autocreate(skel->maps.existing_map), "existing_map_autocreate");
|
|
ASSERT_FALSE(bpf_map__autocreate(skel->maps.missing_map), "missing_map_autocreate");
|
|
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
": <invalid BPF map reference>\n"
|
|
"BPF map 'missing_map' is referenced but wasn't created\n",
|
|
"log_buf");
|
|
|
|
if (env.verbosity > VERBOSE_NONE)
|
|
printf("LOG: \n=================\n%s=================\n", log_buf);
|
|
|
|
cleanup:
|
|
test_log_fixup__destroy(skel);
|
|
}
|
|
|
|
static void missing_kfunc(void)
|
|
{
|
|
char log_buf[8 * 1024];
|
|
struct test_log_fixup* skel;
|
|
int err;
|
|
|
|
skel = test_log_fixup__open();
|
|
if (!ASSERT_OK_PTR(skel, "skel_open"))
|
|
return;
|
|
|
|
bpf_program__set_autoload(skel->progs.use_missing_kfunc, true);
|
|
bpf_program__set_log_buf(skel->progs.use_missing_kfunc, log_buf, sizeof(log_buf));
|
|
|
|
err = test_log_fixup__load(skel);
|
|
if (!ASSERT_ERR(err, "load_fail"))
|
|
goto cleanup;
|
|
|
|
ASSERT_HAS_SUBSTR(log_buf,
|
|
"0: <invalid kfunc call>\n"
|
|
"kfunc 'bpf_nonexistent_kfunc' is referenced but wasn't resolved\n",
|
|
"log_buf");
|
|
|
|
if (env.verbosity > VERBOSE_NONE)
|
|
printf("LOG: \n=================\n%s=================\n", log_buf);
|
|
|
|
cleanup:
|
|
test_log_fixup__destroy(skel);
|
|
}
|
|
|
|
void test_log_fixup(void)
|
|
{
|
|
if (test__start_subtest("bad_core_relo_trunc_none"))
|
|
bad_core_relo(0, TRUNC_NONE /* full buf */);
|
|
if (test__start_subtest("bad_core_relo_trunc_partial"))
|
|
bad_core_relo(300, TRUNC_PARTIAL /* truncate original log a bit */);
|
|
if (test__start_subtest("bad_core_relo_trunc_full"))
|
|
bad_core_relo(240, TRUNC_FULL /* truncate also libbpf's message patch */);
|
|
if (test__start_subtest("bad_core_relo_subprog"))
|
|
bad_core_relo_subprog();
|
|
if (test__start_subtest("missing_map"))
|
|
missing_map();
|
|
if (test__start_subtest("missing_kfunc"))
|
|
missing_kfunc();
|
|
}
|