[PATCH bpf-next 6/9] selftests/bpf: abstract away test log output
From: Andrii Nakryiko <hidden>
Date: 2019-07-26 20:38:15
Also in:
bpf
Subsystem:
bpf [general] (safe dynamic programs and tools), bpf [selftests] (test runners & infrastructure), kernel selftest framework, the rest, xdp (express data path) · Maintainers:
Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, Eduard Zingerman, Kumar Kartikeya Dwivedi, Shuah Khan, Linus Torvalds, David S. Miller, Jakub Kicinski, Jesper Dangaard Brouer, John Fastabend
This patch changes how test output is printed out. By default, if test had no errors, the only output will be a single line with test number, name, and verdict at the end, e.g.: #31 xdp:OK If test had any errors, all log output captured during test execution will be output after test completes. It's possible to force output of log with `-v` (`--verbose`) option, in which case output won't be buffered and will be output immediately. To support this, individual tests are required to use helper methods for logging: `test__printf()` and `test__vprintf()`. Signed-off-by: Andrii Nakryiko <redacted> --- .../selftests/bpf/prog_tests/bpf_obj_id.c | 6 +- .../bpf/prog_tests/bpf_verif_scale.c | 31 ++-- .../bpf/prog_tests/get_stack_raw_tp.c | 4 +- .../selftests/bpf/prog_tests/l4lb_all.c | 2 +- .../selftests/bpf/prog_tests/map_lock.c | 10 +- .../selftests/bpf/prog_tests/send_signal.c | 8 +- .../selftests/bpf/prog_tests/spinlock.c | 2 +- .../bpf/prog_tests/stacktrace_build_id.c | 4 +- .../bpf/prog_tests/stacktrace_build_id_nmi.c | 4 +- .../selftests/bpf/prog_tests/xdp_noinline.c | 3 +- tools/testing/selftests/bpf/test_progs.c | 135 +++++++++++++----- tools/testing/selftests/bpf/test_progs.h | 37 ++++- 12 files changed, 173 insertions(+), 73 deletions(-)
diff --git a/tools/testing/selftests/bpf/prog_tests/bpf_obj_id.c b/tools/testing/selftests/bpf/prog_tests/bpf_obj_id.c
index cb827383db4d..fb5840a62548 100644
--- a/tools/testing/selftests/bpf/prog_tests/bpf_obj_id.c
+++ b/tools/testing/selftests/bpf/prog_tests/bpf_obj_id.c@@ -106,8 +106,8 @@ void test_bpf_obj_id(void) if (CHECK(err || prog_infos[i].type != BPF_PROG_TYPE_SOCKET_FILTER || info_len != sizeof(struct bpf_prog_info) || - (jit_enabled && !prog_infos[i].jited_prog_len) || - (jit_enabled && + (env.jit_enabled && !prog_infos[i].jited_prog_len) || + (env.jit_enabled && !memcmp(jited_insns, zeros, sizeof(zeros))) || !prog_infos[i].xlated_prog_len || !memcmp(xlated_insns, zeros, sizeof(zeros)) ||
@@ -121,7 +121,7 @@ void test_bpf_obj_id(void) err, errno, i, prog_infos[i].type, BPF_PROG_TYPE_SOCKET_FILTER, info_len, sizeof(struct bpf_prog_info), - jit_enabled, + env.jit_enabled, prog_infos[i].jited_prog_len, prog_infos[i].xlated_prog_len, !!memcmp(jited_insns, zeros, sizeof(zeros)),
diff --git a/tools/testing/selftests/bpf/prog_tests/bpf_verif_scale.c b/tools/testing/selftests/bpf/prog_tests/bpf_verif_scale.c
index 2c4d9ef099b4..95f012c417fe 100644
--- a/tools/testing/selftests/bpf/prog_tests/bpf_verif_scale.c
+++ b/tools/testing/selftests/bpf/prog_tests/bpf_verif_scale.c@@ -4,12 +4,15 @@ static int libbpf_debug_print(enum libbpf_print_level level, const char *format, va_list args) { - if (level != LIBBPF_DEBUG) - return vfprintf(stderr, format, args); + if (level != LIBBPF_DEBUG) { + test__vprintf(format, args); + return 0; + } if (!strstr(format, "verifier log")) return 0; - return vfprintf(stderr, "%s", args); + test__vprintf("%s", args); + return 0; } static int check_load(const char *file, enum bpf_prog_type type)
@@ -73,32 +76,38 @@ void test_bpf_verif_scale(void) libbpf_print_fn_t old_print_fn = NULL; int err, i; - if (verifier_stats) + if (env.verifier_stats) { + test__force_log(); old_print_fn = libbpf_swap_print(libbpf_debug_print); + } err = check_load("./loop3.o", BPF_PROG_TYPE_RAW_TRACEPOINT); - printf("test_scale:loop3:%s\n", err ? (error_cnt--, "OK") : "FAIL"); + test__printf("test_scale:loop3:%s\n", + err ? (error_cnt--, "OK") : "FAIL"); for (i = 0; i < ARRAY_SIZE(sched_cls); i++) { err = check_load(sched_cls[i], BPF_PROG_TYPE_SCHED_CLS); - printf("test_scale:%s:%s\n", sched_cls[i], err ? "FAIL" : "OK"); + test__printf("test_scale:%s:%s\n", sched_cls[i], + err ? "FAIL" : "OK"); } for (i = 0; i < ARRAY_SIZE(raw_tp); i++) { err = check_load(raw_tp[i], BPF_PROG_TYPE_RAW_TRACEPOINT); - printf("test_scale:%s:%s\n", raw_tp[i], err ? "FAIL" : "OK"); + test__printf("test_scale:%s:%s\n", raw_tp[i], + err ? "FAIL" : "OK"); } for (i = 0; i < ARRAY_SIZE(cg_sysctl); i++) { err = check_load(cg_sysctl[i], BPF_PROG_TYPE_CGROUP_SYSCTL); - printf("test_scale:%s:%s\n", cg_sysctl[i], err ? "FAIL" : "OK"); + test__printf("test_scale:%s:%s\n", cg_sysctl[i], + err ? "FAIL" : "OK"); } err = check_load("./test_xdp_loop.o", BPF_PROG_TYPE_XDP); - printf("test_scale:test_xdp_loop:%s\n", err ? "FAIL" : "OK"); + test__printf("test_scale:test_xdp_loop:%s\n", err ? "FAIL" : "OK"); err = check_load("./test_seg6_loop.o", BPF_PROG_TYPE_LWT_SEG6LOCAL); - printf("test_scale:test_seg6_loop:%s\n", err ? "FAIL" : "OK"); + test__printf("test_scale:test_seg6_loop:%s\n", err ? "FAIL" : "OK"); - if (verifier_stats) + if (env.verifier_stats) libbpf_set_print(old_print_fn); }
diff --git a/tools/testing/selftests/bpf/prog_tests/get_stack_raw_tp.c b/tools/testing/selftests/bpf/prog_tests/get_stack_raw_tp.c
index 9d73a8f932ac..3d59b3c841fe 100644
--- a/tools/testing/selftests/bpf/prog_tests/get_stack_raw_tp.c
+++ b/tools/testing/selftests/bpf/prog_tests/get_stack_raw_tp.c@@ -41,7 +41,7 @@ static void get_stack_print_output(void *ctx, int cpu, void *data, __u32 size) * just assume it is good if the stack is not empty. * This could be improved in the future. */ - if (jit_enabled) { + if (env.jit_enabled) { found = num_stack > 0; } else { for (i = 0; i < num_stack; i++) {
@@ -58,7 +58,7 @@ static void get_stack_print_output(void *ctx, int cpu, void *data, __u32 size) } } else { num_stack = e->kern_stack_size / sizeof(__u64); - if (jit_enabled) { + if (env.jit_enabled) { good_kern_stack = num_stack > 0; } else { for (i = 0; i < num_stack; i++) {
diff --git a/tools/testing/selftests/bpf/prog_tests/l4lb_all.c b/tools/testing/selftests/bpf/prog_tests/l4lb_all.c
index 20ddca830e68..5ce572c03a5f 100644
--- a/tools/testing/selftests/bpf/prog_tests/l4lb_all.c
+++ b/tools/testing/selftests/bpf/prog_tests/l4lb_all.c@@ -74,7 +74,7 @@ static void test_l4lb(const char *file) } if (bytes != MAGIC_BYTES * NUM_ITER * 2 || pkts != NUM_ITER * 2) { error_cnt++; - printf("test_l4lb:FAIL:stats %lld %lld\n", bytes, pkts); + test__printf("test_l4lb:FAIL:stats %lld %lld\n", bytes, pkts); } out: bpf_object__close(obj);
diff --git a/tools/testing/selftests/bpf/prog_tests/map_lock.c b/tools/testing/selftests/bpf/prog_tests/map_lock.c
index ee99368c595c..2e78217ed3fd 100644
--- a/tools/testing/selftests/bpf/prog_tests/map_lock.c
+++ b/tools/testing/selftests/bpf/prog_tests/map_lock.c@@ -9,12 +9,12 @@ static void *parallel_map_access(void *arg) for (i = 0; i < 10000; i++) { err = bpf_map_lookup_elem_flags(map_fd, &key, vars, BPF_F_LOCK); if (err) { - printf("lookup failed\n"); + test__printf("lookup failed\n"); error_cnt++; goto out; } if (vars[0] != 0) { - printf("lookup #%d var[0]=%d\n", i, vars[0]); + test__printf("lookup #%d var[0]=%d\n", i, vars[0]); error_cnt++; goto out; }
@@ -22,8 +22,8 @@ static void *parallel_map_access(void *arg) for (j = 2; j < 17; j++) { if (vars[j] == rnd) continue; - printf("lookup #%d var[1]=%d var[%d]=%d\n", - i, rnd, j, vars[j]); + test__printf("lookup #%d var[1]=%d var[%d]=%d\n", + i, rnd, j, vars[j]); error_cnt++; goto out; }
@@ -43,7 +43,7 @@ void test_map_lock(void) err = bpf_prog_load(file, BPF_PROG_TYPE_CGROUP_SKB, &obj, &prog_fd); if (err) { - printf("test_map_lock:bpf_prog_load errno %d\n", errno); + test__printf("test_map_lock:bpf_prog_load errno %d\n", errno); goto close_prog; } map_fd[0] = bpf_find_map(__func__, obj, "hash_map");
diff --git a/tools/testing/selftests/bpf/prog_tests/send_signal.c b/tools/testing/selftests/bpf/prog_tests/send_signal.c
index 54218ee3c004..d950f4558897 100644
--- a/tools/testing/selftests/bpf/prog_tests/send_signal.c
+++ b/tools/testing/selftests/bpf/prog_tests/send_signal.c@@ -202,8 +202,8 @@ static int test_send_signal_nmi(void) -1 /* cpu */, -1 /* group_fd */, 0 /* flags */); if (pmu_fd == -1) { if (errno == ENOENT) { - printf("%s:SKIP:no PERF_COUNT_HW_CPU_CYCLES\n", - __func__); + test__printf("%s:SKIP:no PERF_COUNT_HW_CPU_CYCLES\n", + __func__); return 0; } /* Let the test fail with a more informative message */
@@ -222,8 +222,4 @@ void test_send_signal(void) ret |= test_send_signal_tracepoint(); ret |= test_send_signal_perf(); ret |= test_send_signal_nmi(); - if (!ret) - printf("test_send_signal:OK\n"); - else - printf("test_send_signal:FAIL\n"); }
diff --git a/tools/testing/selftests/bpf/prog_tests/spinlock.c b/tools/testing/selftests/bpf/prog_tests/spinlock.c
index 114ebe6a438e..deb2db5b85b0 100644
--- a/tools/testing/selftests/bpf/prog_tests/spinlock.c
+++ b/tools/testing/selftests/bpf/prog_tests/spinlock.c@@ -12,7 +12,7 @@ void test_spinlock(void) err = bpf_prog_load(file, BPF_PROG_TYPE_CGROUP_SKB, &obj, &prog_fd); if (err) { - printf("test_spin_lock:bpf_prog_load errno %d\n", errno); + test__printf("test_spin_lock:bpf_prog_load errno %d\n", errno); goto close_prog; } for (i = 0; i < 4; i++)
diff --git a/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id.c b/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id.c
index ac44fda84833..356d2c017a9c 100644
--- a/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id.c
+++ b/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id.c@@ -109,8 +109,8 @@ void test_stacktrace_build_id(void) if (build_id_matches < 1 && retry--) { bpf_link__destroy(link); bpf_object__close(obj); - printf("%s:WARN:Didn't find expected build ID from the map, retrying\n", - __func__); + test__printf("%s:WARN:Didn't find expected build ID from the map, retrying\n", + __func__); goto retry; }
diff --git a/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id_nmi.c b/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id_nmi.c
index 9557b7dfb782..f44f2c159714 100644
--- a/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id_nmi.c
+++ b/tools/testing/selftests/bpf/prog_tests/stacktrace_build_id_nmi.c@@ -140,8 +140,8 @@ void test_stacktrace_build_id_nmi(void) if (build_id_matches < 1 && retry--) { bpf_link__destroy(link); bpf_object__close(obj); - printf("%s:WARN:Didn't find expected build ID from the map, retrying\n", - __func__); + test__printf("%s:WARN:Didn't find expected build ID from the map, retrying\n", + __func__); goto retry; }
diff --git a/tools/testing/selftests/bpf/prog_tests/xdp_noinline.c b/tools/testing/selftests/bpf/prog_tests/xdp_noinline.c
index 09e6b46f5515..b5404494b8aa 100644
--- a/tools/testing/selftests/bpf/prog_tests/xdp_noinline.c
+++ b/tools/testing/selftests/bpf/prog_tests/xdp_noinline.c@@ -75,7 +75,8 @@ void test_xdp_noinline(void) } if (bytes != MAGIC_BYTES * NUM_ITER * 2 || pkts != NUM_ITER * 2) { error_cnt++; - printf("test_xdp_noinline:FAIL:stats %lld %lld\n", bytes, pkts); + test__printf("test_xdp_noinline:FAIL:stats %lld %lld\n", + bytes, pkts); } out: bpf_object__close(obj);
diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index 94b6951b90b3..3cf3ebda1d31 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c@@ -6,9 +6,75 @@ #include <argp.h> #include <string.h> +/* defined in test_progs.h */ +struct test_env env = { + .test_num_selector = -1, +}; int error_cnt, pass_cnt; -bool jit_enabled; -bool verifier_stats = false; + +struct prog_test_def { + const char *test_name; + int test_num; + void (*run_test)(void); + bool force_log; + int pass_cnt; + int error_cnt; + bool tested; +}; + +void test__force_log() { + env.test->force_log = true; +} + +void test__vprintf(const char *fmt, va_list args) +{ + size_t rem_sz; + int ret; + + if (env.verbose || (env.test && env.test->force_log)) { + vfprintf(stderr, fmt, args); + return; + } + +try_again: + rem_sz = env.log_cap - env.log_cnt; + if (rem_sz) { + ret = vsnprintf(env.log_buf + env.log_cnt, rem_sz, fmt, args); + if (ret < 0) { + fprintf(stderr, "failed to log message w/ fmt '%s'\n", fmt); + return; + } + } + + if (ret >= rem_sz) { + size_t new_sz = env.log_cap * 3 / 2; + char *new_buf; + + if (new_sz < 4096) + new_sz = 4096; + + new_buf = realloc(env.log_buf, new_sz); + if (!new_buf) { + fprintf(stderr, "failed to realloc log buffer: %d\n", + errno); + return; + } + env.log_buf = new_buf; + env.log_cap = new_sz; + goto try_again; + } + + env.log_cnt += ret + 1; +} + +void test__printf(const char *fmt, ...) +{ + va_list args; + + va_start(args, fmt); + test__vprintf(fmt, args); + va_end(args); +} struct ipv4_packet pkt_v4 = { .eth.h_proto = __bpf_constant_htons(ETH_P_IP),
@@ -163,20 +229,15 @@ void *spin_lock_thread(void *arg) #include <prog_tests/tests.h> #undef DEFINE_TEST -struct prog_test_def { - const char *test_name; - int test_num; - void (*run_test)(void); -}; - static struct prog_test_def prog_test_defs[] = { -#define DEFINE_TEST(name) { \ - .test_name = #name, \ - .run_test = &test_##name, \ +#define DEFINE_TEST(name) { \ + .test_name = #name, \ + .run_test = &test_##name, \ }, #include <prog_tests/tests.h> #undef DEFINE_TEST }; +const int prog_test_cnt = ARRAY_SIZE(prog_test_defs); const char *argp_program_version = "test_progs 0.1"; const char *argp_program_bug_address = "<bpf@vger.kernel.org>";
@@ -186,7 +247,6 @@ enum ARG_KEYS { ARG_TEST_NUM = 'n', ARG_TEST_NAME = 't', ARG_VERIFIER_STATS = 's', - ARG_VERBOSE = 'v', };
@@ -202,24 +262,13 @@ static const struct argp_option opts[] = { {}, }; -struct test_env { - int test_num_selector; - const char *test_name_selector; - bool verifier_stats; - bool verbose; - bool very_verbose; -}; - -static struct test_env env = { - .test_num_selector = -1, -}; - static int libbpf_print_fn(enum libbpf_print_level level, const char *format, va_list args) { if (!env.very_verbose && level == LIBBPF_DEBUG) return 0; - return vfprintf(stderr, format, args); + test__vprintf(format, args); + return 0; } static error_t parse_arg(int key, char *arg, struct argp_state *state)
@@ -267,7 +316,6 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state) return 0; } - int main(int argc, char **argv) { static const struct argp argp = {
@@ -275,7 +323,6 @@ int main(int argc, char **argv) .parser = parse_arg, .doc = argp_program_doc, }; - struct prog_test_def *test; int err, i; err = argp_parse(&argp, argc, argv, 0, NULL, &env);
@@ -286,13 +333,14 @@ int main(int argc, char **argv) srand(time(NULL)); - jit_enabled = is_jit_enabled(); + env.jit_enabled = is_jit_enabled(); - verifier_stats = env.verifier_stats; - - for (i = 0; i < ARRAY_SIZE(prog_test_defs); i++) { - test = &prog_test_defs[i]; + for (i = 0; i < prog_test_cnt; i++) { + struct prog_test_def *test = &prog_test_defs[i]; + int old_pass_cnt = pass_cnt; + int old_error_cnt = error_cnt; + env.test = test; test->test_num = i + 1; if (env.test_num_selector >= 0 &&
@@ -303,8 +351,29 @@ int main(int argc, char **argv) continue; test->run_test(); + test->tested = true; + test->pass_cnt = pass_cnt - old_pass_cnt; + test->error_cnt = error_cnt - old_error_cnt; + if (test->error_cnt) + env.fail_cnt++; + else + env.succ_cnt++; + + if (env.verbose || test->force_log || test->error_cnt) { + if (env.log_cnt) { + fprintf(stdout, "%s", env.log_buf); + if (env.log_buf[env.log_cnt - 1] != '\n') + fprintf(stdout, "\n"); + } + } + env.log_cnt = 0; + + printf("#%d %s:%s\n", test->test_num, test->test_name, + test->error_cnt ? "FAIL" : "OK"); } + printf("Summary: %d PASSED, %d FAILED\n", env.succ_cnt, env.fail_cnt); + + free(env.log_buf); - printf("Summary: %d PASSED, %d FAILED\n", pass_cnt, error_cnt); return error_cnt ? EXIT_FAILURE : EXIT_SUCCESS; }
diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
index 49e0f7d85643..62f55a4231e9 100644
--- a/tools/testing/selftests/bpf/test_progs.h
+++ b/tools/testing/selftests/bpf/test_progs.h@@ -38,9 +38,33 @@ typedef __u16 __sum16; #include "trace_helpers.h" #include "flow_dissector_load.h" -extern int error_cnt, pass_cnt; -extern bool jit_enabled; -extern bool verifier_stats; +struct prog_test_def; + +struct test_env { + int test_num_selector; + const char *test_name_selector; + bool verifier_stats; + bool verbose; + bool very_verbose; + + bool jit_enabled; + + struct prog_test_def *test; + char *log_buf; + size_t log_cnt; + size_t log_cap; + + int succ_cnt; + int fail_cnt; +}; + +extern int error_cnt; +extern int pass_cnt; +extern struct test_env env; + +extern void test__printf(const char *fmt, ...); +extern void test__vprintf(const char *fmt, va_list args); +extern void test__force_log(); #define MAGIC_BYTES 123
@@ -64,11 +88,12 @@ extern struct ipv6_packet pkt_v6; int __ret = !!(condition); \ if (__ret) { \ error_cnt++; \ - printf("%s:FAIL:%s ", __func__, tag); \ - printf(format); \ + test__printf("%s:FAIL:%s ", __func__, tag); \ + test__printf(format); \ } else { \ pass_cnt++; \ - printf("%s:PASS:%s %d nsec\n", __func__, tag, duration);\ + test__printf("%s:PASS:%s %d nsec\n", \ + __func__, tag, duration); \ } \ __ret; \ })
--
2.17.1