selftests/bpf: Refactor prog_tests logging and test execution

This is a pre-req to add separate logging for each subtest in
test_progs.

Move all the mutable test data to the test_result struct.
Move per-test init/de-init into the run_one_test function.
Consolidate data aggregation and final log output in
calculate_and_print_summary function.
As a side effect, this patch fixes double counting of errors
for subtests and possible duplicate output of subtest log
on failures.

Also, add prog_tests_framework.c test to verify some of the
counting logic.

As part of verification, confirmed that number of reported
tests is the same before and after the change for both parallel
and sequential test execution.

Signed-off-by: Mykola Lysenko <mykolal@fb.com>
Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
Link: https://lore.kernel.org/bpf/20220418222507.1726259-1-mykolal@fb.com

1 files changed, 117 insertions, 211 deletions

diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index dcad9871f556..c536d1d29d57 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c
@@ -51,19 +51,8 @@ struct prog_test_def {
 	int test_num;
 	void (*run_test)(void);
 	void (*run_serial_test)(void);
-	bool force_log;
-	int error_cnt;
-	int skip_cnt;
-	int sub_succ_cnt;
 	bool should_run;
-	bool tested;
 	bool need_cgroup_cleanup;
-
-	char *subtest_name;
-	int subtest_num;
-
-	/* store counts before subtest started */
-	int old_error_cnt;
 };
 
 /* Override C runtime library's usleep() implementation to ensure nanosleep()
@@ -141,35 +130,32 @@ static bool should_run_subtest(struct test_selector *sel,
 	return subtest_num < subtest_sel->num_set_len && subtest_sel->num_set[subtest_num];
 }
 
-static void dump_test_log(const struct prog_test_def *test, bool failed)
+static void dump_test_log(const struct prog_test_def *test,
+			  const struct test_state *test_state,
+			  bool force_failed)
 {
-	if (stdout == env.stdout)
-		return;
+	bool failed = test_state->error_cnt > 0 || force_failed;
 
 	/* worker always holds log */
 	if (env.worker_id != -1)
 		return;
 
-	fflush(stdout); /* exports env.log_buf & env.log_cnt */
+	fflush(stdout); /* exports test_state->log_buf & test_state->log_cnt */
+
+	fprintf(env.stdout, "#%-3d %s:%s\n",
+		test->test_num, test->test_name,
+		failed ? "FAIL" : (test_state->skip_cnt ? "SKIP" : "OK"));
 
-	if (env.verbosity > VERBOSE_NONE || test->force_log || failed) {
-		if (env.log_cnt) {
-			env.log_buf[env.log_cnt] = '\0';
-			fprintf(env.stdout, "%s", env.log_buf);
-			if (env.log_buf[env.log_cnt - 1] != '\n')
+	if (env.verbosity > VERBOSE_NONE || test_state->force_log || failed) {
+		if (test_state->log_cnt) {
+			test_state->log_buf[test_state->log_cnt] = '\0';
+			fprintf(env.stdout, "%s", test_state->log_buf);
+			if (test_state->log_buf[test_state->log_cnt - 1] != '\n')
 				fprintf(env.stdout, "\n");
 		}
 	}
 }
 
-static void skip_account(void)
-{
-	if (env.test->skip_cnt) {
-		env.skip_cnt++;
-		env.test->skip_cnt = 0;
-	}
-}
-
 static void stdio_restore(void);
 
 /* A bunch of tests set custom affinity per-thread and/or per-process. Reset
@@ -219,72 +205,78 @@ static void restore_netns(void)
 void test__end_subtest(void)
 {
 	struct prog_test_def *test = env.test;
-	int sub_error_cnt = test->error_cnt - test->old_error_cnt;
-
-	dump_test_log(test, sub_error_cnt);
+	struct test_state *state = env.test_state;
+	int sub_error_cnt = state->error_cnt - state->old_error_cnt;
 
 	fprintf(stdout, "#%d/%d %s/%s:%s\n",
-	       test->test_num, test->subtest_num, test->test_name, test->subtest_name,
-	       sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
+	       test->test_num, state->subtest_num, test->test_name, state->subtest_name,
+	       sub_error_cnt ? "FAIL" : (state->subtest_skip_cnt ? "SKIP" : "OK"));
 
-	if (sub_error_cnt)
-		test->error_cnt++;
-	else if (test->skip_cnt == 0)
-		test->sub_succ_cnt++;
-	skip_account();
+	if (sub_error_cnt == 0) {
+		if (state->subtest_skip_cnt == 0) {
+			state->sub_succ_cnt++;
+		} else {
+			state->subtest_skip_cnt = 0;
+			state->skip_cnt++;
+		}
+	}
 
-	free(test->subtest_name);
-	test->subtest_name = NULL;
+	free(state->subtest_name);
+	state->subtest_name = NULL;
 }
 
 bool test__start_subtest(const char *subtest_name)
 {
 	struct prog_test_def *test = env.test;
+	struct test_state *state = env.test_state;
 
-	if (test->subtest_name)
+	if (state->subtest_name)
 		test__end_subtest();
 
-	test->subtest_num++;
+	state->subtest_num++;
 
 	if (!subtest_name || !subtest_name[0]) {
 		fprintf(env.stderr,
 			"Subtest #%d didn't provide sub-test name!\n",
-			test->subtest_num);
+			state->subtest_num);
 		return false;
 	}
 
 	if (!should_run_subtest(&env.test_selector,
 				&env.subtest_selector,
-				test->subtest_num,
+				state->subtest_num,
 				test->test_name,
 				subtest_name))
 		return false;
 
-	test->subtest_name = strdup(subtest_name);
-	if (!test->subtest_name) {
+	state->subtest_name = strdup(subtest_name);
+	if (!state->subtest_name) {
 		fprintf(env.stderr,
 			"Subtest #%d: failed to copy subtest name!\n",
-			test->subtest_num);
+			state->subtest_num);
 		return false;
 	}
-	env.test->old_error_cnt = env.test->error_cnt;
+	state->old_error_cnt = state->error_cnt;
 
 	return true;
 }
 
 void test__force_log(void)
 {
-	env.test->force_log = true;
+	env.test_state->force_log = true;
 }
 
 void test__skip(void)
 {
-	env.test->skip_cnt++;
+	if (env.test_state->subtest_name)
+		env.test_state->subtest_skip_cnt++;
+	else
+		env.test_state->skip_cnt++;
 }
 
 void test__fail(void)
 {
-	env.test->error_cnt++;
+	env.test_state->error_cnt++;
 }
 
 int test__join_cgroup(const char *path)
@@ -517,8 +509,11 @@ static struct prog_test_def prog_test_defs[] = {
 #include <prog_tests/tests.h>
 #undef DEFINE_TEST
 };
+
 static const int prog_test_cnt = ARRAY_SIZE(prog_test_defs);
 
+static struct test_state test_states[ARRAY_SIZE(prog_test_defs)];
+
 const char *argp_program_version = "test_progs 0.1";
 const char *argp_program_bug_address = "<bpf@vger.kernel.org>";
 static const char argp_program_doc[] = "BPF selftests test runner";
@@ -701,7 +696,7 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state)
 	return 0;
 }
 
-static void stdio_hijack(void)
+static void stdio_hijack(char **log_buf, size_t *log_cnt)
 {
 #ifdef __GLIBC__
 	env.stdout = stdout;
@@ -715,7 +710,7 @@ static void stdio_hijack(void)
 	/* stdout and stderr -> buffer */
 	fflush(stdout);
 
-	stdout = open_memstream(&env.log_buf, &env.log_cnt);
+	stdout = open_memstream(log_buf, log_cnt);
 	if (!stdout) {
 		stdout = env.stdout;
 		perror("open_memstream");
@@ -818,7 +813,7 @@ void crash_handler(int signum)
 	sz = backtrace(bt, ARRAY_SIZE(bt));
 
 	if (env.test)
-		dump_test_log(env.test, true);
+		dump_test_log(env.test, env.test_state, true);
 	if (env.stdout)
 		stdio_restore();
 	if (env.worker_id != -1)
@@ -840,17 +835,6 @@ static int current_test_idx;
 static pthread_mutex_t current_test_lock;
 static pthread_mutex_t stdout_output_lock;
 
-struct test_result {
-	int error_cnt;
-	int skip_cnt;
-	int sub_succ_cnt;
-
-	size_t log_cnt;
-	char *log_buf;
-};
-
-static struct test_result test_results[ARRAY_SIZE(prog_test_defs)];
-
 static inline const char *str_msg(const struct msg *msg, char *buf)
 {
 	switch (msg->type) {
@@ -904,8 +888,12 @@ static int recv_message(int sock, struct msg *msg)
 static void run_one_test(int test_num)
 {
 	struct prog_test_def *test = &prog_test_defs[test_num];
+	struct test_state *state = &test_states[test_num];
 
 	env.test = test;
+	env.test_state = state;
+
+	stdio_hijack(&state->log_buf, &state->log_cnt);
 
 	if (test->run_test)
 		test->run_test();
@@ -913,17 +901,19 @@ static void run_one_test(int test_num)
 		test->run_serial_test();
 
 	/* ensure last sub-test is finalized properly */
-	if (test->subtest_name)
+	if (state->subtest_name)
 		test__end_subtest();
 
-	test->tested = true;
+	state->tested = true;
 
-	dump_test_log(test, test->error_cnt);
+	dump_test_log(test, state, false);
 
 	reset_affinity();
 	restore_netns();
 	if (test->need_cgroup_cleanup)
 		cleanup_cgroup_environment();
+
+	stdio_restore();
 }
 
 struct dispatch_data {
@@ -942,7 +932,7 @@ static void *dispatch_thread(void *ctx)
 	while (true) {
 		int test_to_run = -1;
 		struct prog_test_def *test;
-		struct test_result *result;
+		struct test_state *state;
 
 		/* grab a test */
 		{
@@ -989,16 +979,15 @@ static void *dispatch_thread(void *ctx)
 			if (test_to_run != msg_test_done.test_done.test_num)
 				goto error;
 
-			test->tested = true;
-			result = &test_results[test_to_run];
-
-			result->error_cnt = msg_test_done.test_done.error_cnt;
-			result->skip_cnt = msg_test_done.test_done.skip_cnt;
-			result->sub_succ_cnt = msg_test_done.test_done.sub_succ_cnt;
+			state = &test_states[test_to_run];
+			state->tested = true;
+			state->error_cnt = msg_test_done.test_done.error_cnt;
+			state->skip_cnt = msg_test_done.test_done.skip_cnt;
+			state->sub_succ_cnt = msg_test_done.test_done.sub_succ_cnt;
 
 			/* collect all logs */
 			if (msg_test_done.test_done.have_log) {
-				log_fp = open_memstream(&result->log_buf, &result->log_cnt);
+				log_fp = open_memstream(&state->log_buf, &state->log_cnt);
 				if (!log_fp)
 					goto error;
 
@@ -1017,25 +1006,11 @@ static void *dispatch_thread(void *ctx)
 				fclose(log_fp);
 				log_fp = NULL;
 			}
-			/* output log */
-			{
-				pthread_mutex_lock(&stdout_output_lock);
-
-				if (result->log_cnt) {
-					result->log_buf[result->log_cnt] = '\0';
-					fprintf(stdout, "%s", result->log_buf);
-					if (result->log_buf[result->log_cnt - 1] != '\n')
-						fprintf(stdout, "\n");
-				}
-
-				fprintf(stdout, "#%d %s:%s\n",
-					test->test_num, test->test_name,
-					result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
-
-				pthread_mutex_unlock(&stdout_output_lock);
-			}
-
 		} /* wait for test done */
+
+		pthread_mutex_lock(&stdout_output_lock);
+		dump_test_log(test, state, false);
+		pthread_mutex_unlock(&stdout_output_lock);
 	} /* while (true) */
 error:
 	if (env.debug)
@@ -1057,38 +1032,50 @@ done:
 	return NULL;
 }
 
-static void print_all_error_logs(void)
+static void calculate_summary_and_print_errors(struct test_env *env)
 {
 	int i;
+	int succ_cnt = 0, fail_cnt = 0, sub_succ_cnt = 0, skip_cnt = 0;
 
-	if (env.fail_cnt)
-		fprintf(stdout, "\nAll error logs:\n");
+	for (i = 0; i < prog_test_cnt; i++) {
+		struct test_state *state = &test_states[i];
+
+		if (!state->tested)
+			continue;
+
+		sub_succ_cnt += state->sub_succ_cnt;
+		skip_cnt += state->skip_cnt;
+
+		if (state->error_cnt)
+			fail_cnt++;
+		else
+			succ_cnt++;
+	}
+
+	if (fail_cnt)
+		printf("\nAll error logs:\n");
 
 	/* print error logs again */
 	for (i = 0; i < prog_test_cnt; i++) {
-		struct prog_test_def *test;
-		struct test_result *result;
-
-		test = &prog_test_defs[i];
-		result = &test_results[i];
+		struct prog_test_def *test = &prog_test_defs[i];
+		struct test_state *state = &test_states[i];
 
-		if (!test->tested || !result->error_cnt)
+		if (!state->tested || !state->error_cnt)
 			continue;
 
-		fprintf(stdout, "\n#%d %s:%s\n",
-			test->test_num, test->test_name,
-			result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
-
-		if (result->log_cnt) {
-			result->log_buf[result->log_cnt] = '\0';
-			fprintf(stdout, "%s", result->log_buf);
-			if (result->log_buf[result->log_cnt - 1] != '\n')
-				fprintf(stdout, "\n");
-		}
+		dump_test_log(test, state, true);
 	}
+
+	printf("Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
+	       succ_cnt, sub_succ_cnt, skip_cnt, fail_cnt);
+
+	env->succ_cnt = succ_cnt;
+	env->sub_succ_cnt = sub_succ_cnt;
+	env->fail_cnt = fail_cnt;
+	env->skip_cnt = skip_cnt;
 }
 
-static int server_main(void)
+static void server_main(void)
 {
 	pthread_t *dispatcher_threads;
 	struct dispatch_data *data;
@@ -1144,60 +1131,18 @@ static int server_main(void)
 
 	for (int i = 0; i < prog_test_cnt; i++) {
 		struct prog_test_def *test = &prog_test_defs[i];
-		struct test_result *result = &test_results[i];
 
 		if (!test->should_run || !test->run_serial_test)
 			continue;
 
-		stdio_hijack();
-
 		run_one_test(i);
-
-		stdio_restore();
-		if (env.log_buf) {
-			result->log_cnt = env.log_cnt;
-			result->log_buf = strdup(env.log_buf);
-
-			free(env.log_buf);
-			env.log_buf = NULL;
-			env.log_cnt = 0;
-		}
-		restore_netns();
-
-		fprintf(stdout, "#%d %s:%s\n",
-			test->test_num, test->test_name,
-			test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
-
-		result->error_cnt = test->error_cnt;
-		result->skip_cnt = test->skip_cnt;
-		result->sub_succ_cnt = test->sub_succ_cnt;
 	}
 
 	/* generate summary */
 	fflush(stderr);
 	fflush(stdout);
 
-	for (i = 0; i < prog_test_cnt; i++) {
-		struct prog_test_def *current_test;
-		struct test_result *result;
-
-		current_test = &prog_test_defs[i];
-		result = &test_results[i];
-
-		if (!current_test->tested)
-			continue;
-
-		env.succ_cnt += result->error_cnt ? 0 : 1;
-		env.skip_cnt += result->skip_cnt;
-		if (result->error_cnt)
-			env.fail_cnt++;
-		env.sub_succ_cnt += result->sub_succ_cnt;
-	}
-
-	print_all_error_logs();
-
-	fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
-		env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
+	calculate_summary_and_print_errors(&env);
 
 	/* reap all workers */
 	for (i = 0; i < env.workers; i++) {
@@ -1207,8 +1152,6 @@ static int server_main(void)
 		if (pid != env.worker_pids[i])
 			perror("Unable to reap worker");
 	}
-
-	return 0;
 }
 
 static int worker_main(int sock)
@@ -1229,35 +1172,29 @@ static int worker_main(int sock)
 					env.worker_id);
 			goto out;
 		case MSG_DO_TEST: {
-			int test_to_run;
-			struct prog_test_def *test;
+			int test_to_run = msg.do_test.test_num;
+			struct prog_test_def *test = &prog_test_defs[test_to_run];
+			struct test_state *state = &test_states[test_to_run];
 			struct msg msg_done;
 
-			test_to_run = msg.do_test.test_num;
-			test = &prog_test_defs[test_to_run];
-
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s running.\n",
 					env.worker_id,
 					test_to_run + 1,
 					test->test_name);
 
-			stdio_hijack();
-
 			run_one_test(test_to_run);
 
-			stdio_restore();
-
 			memset(&msg_done, 0, sizeof(msg_done));
 			msg_done.type = MSG_TEST_DONE;
 			msg_done.test_done.test_num = test_to_run;
-			msg_done.test_done.error_cnt = test->error_cnt;
-			msg_done.test_done.skip_cnt = test->skip_cnt;
-			msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
+			msg_done.test_done.error_cnt = state->error_cnt;
+			msg_done.test_done.skip_cnt = state->skip_cnt;
+			msg_done.test_done.sub_succ_cnt = state->sub_succ_cnt;
 			msg_done.test_done.have_log = false;
 
-			if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
-				if (env.log_cnt)
+			if (env.verbosity > VERBOSE_NONE || state->force_log || state->error_cnt) {
+				if (state->log_cnt)
 					msg_done.test_done.have_log = true;
 			}
 			if (send_message(sock, &msg_done) < 0) {
@@ -1270,8 +1207,8 @@ static int worker_main(int sock)
 				char *src;
 				size_t slen;
 
-				src = env.log_buf;
-				slen = env.log_cnt;
+				src = state->log_buf;
+				slen = state->log_cnt;
 				while (slen) {
 					struct msg msg_log;
 					char *dest;
@@ -1291,10 +1228,10 @@ static int worker_main(int sock)
 					assert(send_message(sock, &msg_log) >= 0);
 				}
 			}
-			if (env.log_buf) {
-				free(env.log_buf);
-				env.log_buf = NULL;
-				env.log_cnt = 0;
+			if (state->log_buf) {
+				free(state->log_buf);
+				state->log_buf = NULL;
+				state->log_cnt = 0;
 			}
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s done.\n",
@@ -1425,7 +1362,6 @@ int main(int argc, char **argv)
 
 	for (i = 0; i < prog_test_cnt; i++) {
 		struct prog_test_def *test = &prog_test_defs[i];
-		struct test_result *result;
 
 		if (!test->should_run)
 			continue;
@@ -1441,34 +1377,7 @@ int main(int argc, char **argv)
 			continue;
 		}
 
-		stdio_hijack();
-
 		run_one_test(i);
-
-		stdio_restore();
-
-		fprintf(env.stdout, "#%d %s:%s\n",
-			test->test_num, test->test_name,
-			test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
-
-		result = &test_results[i];
-		result->error_cnt = test->error_cnt;
-		if (env.log_buf) {
-			result->log_buf = strdup(env.log_buf);
-			result->log_cnt = env.log_cnt;
-
-			free(env.log_buf);
-			env.log_buf = NULL;
-			env.log_cnt = 0;
-		}
-
-		if (test->error_cnt)
-			env.fail_cnt++;
-		else
-			env.succ_cnt++;
-
-		skip_account();
-		env.sub_succ_cnt += test->sub_succ_cnt;
 	}
 
 	if (env.get_test_cnt) {
@@ -1479,10 +1388,7 @@ int main(int argc, char **argv)
 	if (env.list_test_names)
 		goto out;
 
-	print_all_error_logs();
-
-	fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
-		env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
+	calculate_summary_and_print_errors(&env);
 
 	close(env.saved_netns_fd);
 out: