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 <andriin@fb.com>
Signed-off-by: Alexei Starovoitov <ast@kernel.org>

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) ||
+			  (env.jit_enabled && !prog_infos[i].jited_prog_len) ||
-			  (jit_enabled &&
+			  (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)),

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)
+	if (level != LIBBPF_DEBUG) {
-		return vfprintf(stderr, format, args);
+		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);
 }

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++) {

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);

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",
+			test__printf("lookup #%d var[1]=%d var[%d]=%d\n",
-			       i, rnd, j, vars[j]);
+				     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");

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",
+			test__printf("%s:SKIP:no PERF_COUNT_HW_CPU_CYCLES\n",
-				__func__);
+				     __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");
 }

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++)

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",
+		test__printf("%s:WARN:Didn't find expected build ID from the map, retrying\n",
-		       __func__);
+			     __func__);
 		goto retry;
 	}
 

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",
+		test__printf("%s:WARN:Didn't find expected build ID from the map, retrying\n",
-		       __func__);
+			     __func__);
 		goto retry;
 	}
 

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);

tools/testing/selftests/bpf/test_progs.c

@@ -6,9 +6,85 @@
 #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 = 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 <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) {	      \
+#define DEFINE_TEST(name) {		\
-	.test_name = #name,	      \
+	.test_name = #name,		\
-	.run_test = &test_##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 +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 < prog_test_cnt; i++) {
-
+		struct prog_test_def *test = &prog_test_defs[i];
-	for (i = 0; i < ARRAY_SIZE(prog_test_defs); i++) {
+		int old_pass_cnt = pass_cnt;
-		test = &prog_test_defs[i];
+		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;
 }

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;
+struct prog_test_def;
-extern bool jit_enabled;
+
-extern bool verifier_stats;
+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);			\
+		test__printf("%s:FAIL:%s ", __func__, tag);		\
-		printf(format);						\
+		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;								\
 })