From 0ff97e56c0986ea6633083c3487d9231bbbd881b Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Sat, 27 Jul 2019 20:25:28 -0700 Subject: [PATCH] selftests/bpf: abstract away test log output 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 Signed-off-by: Alexei Starovoitov --- .../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 | 147 ++++++++++++++---- tools/testing/selftests/bpf/test_progs.h | 37 ++++- 12 files changed, 184 insertions(+), 74 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 ceddb8cc86f4..b59017279e0b 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_set_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 @@ retry: 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 @@ retry: 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..1b7470d3da22 100644 --- a/tools/testing/selftests/bpf/test_progs.c +++ b/tools/testing/selftests/bpf/test_progs.c @@ -6,9 +6,85 @@ #include #include +/* 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 = 0; + + 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) { + va_list ap; + + va_copy(ap, args); + /* we reserved extra byte for \0 at the end */ + ret = vsnprintf(env.log_buf + env.log_cnt, rem_sz + 1, fmt, ap); + va_end(ap); + + if (ret < 0) { + env.log_buf[env.log_cnt] = '\0'; + fprintf(stderr, "failed to log w/ fmt '%s'\n", fmt); + return; + } + } + + if (!rem_sz || ret > rem_sz) { + size_t new_sz = env.log_cap * 3 / 2; + char *new_buf; + + if (new_sz < 4096) + new_sz = 4096; + if (new_sz < ret + env.log_cnt) + new_sz = ret + env.log_cnt; + + /* +1 for guaranteed space for terminating \0 */ + new_buf = realloc(env.log_buf, new_sz + 1); + 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; +} + +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 +239,15 @@ void *spin_lock_thread(void *arg) #include #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 #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 = ""; @@ -186,7 +257,6 @@ enum ARG_KEYS { ARG_TEST_NUM = 'n', ARG_TEST_NAME = 't', ARG_VERIFIER_STATS = 's', - ARG_VERBOSE = 'v', }; @@ -202,24 +272,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 +326,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 +333,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 +343,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 +361,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; \ })