[v2,bpf-next] bpf/selftests: add granular subtest output for prog_test

Commit Message

Mykola Lysenko April 27, 2022, 4:13 a.m. UTC

Implement per subtest log collection for both parallel
and sequential test execution. This allows granular
per-subtest error output in the 'All error logs' section.
Add subtest log transfer into the protocol during the
parallel test execution.

Move all test log printing logic into dump_test_log
function. One exception is the output of test names when
verbose printing is enabled. Move test name/result
printing into separate functions to avoid repetition.

Print all successful subtest results in the log. Print
only failed test logs when test does not have subtests.
Or only failed subtests' logs when test has subtests.

Disable 'All error logs' output when verbose mode is
enabled. This functionality was already broken and is
causing confusion.

Signed-off-by: Mykola Lysenko <[e-mail]>
---
 tools/testing/selftests/bpf/test_progs.c | 640 +++++++++++++++++------
 tools/testing/selftests/bpf/test_progs.h |  35 +-
 2 files changed, 499 insertions(+), 176 deletions(-)

Comments

Andrii Nakryiko April 27, 2022, 10:38 p.m. UTC | #1

On Tue, Apr 26, 2022 at 9:14 PM Mykola Lysenko <[e-mail]> wrote:
>
> Implement per subtest log collection for both parallel
> and sequential test execution. This allows granular
> per-subtest error output in the 'All error logs' section.
> Add subtest log transfer into the protocol during the
> parallel test execution.
>
> Move all test log printing logic into dump_test_log
> function. One exception is the output of test names when
> verbose printing is enabled. Move test name/result
> printing into separate functions to avoid repetition.
>
> Print all successful subtest results in the log. Print
> only failed test logs when test does not have subtests.
> Or only failed subtests' logs when test has subtests.
>
> Disable 'All error logs' output when verbose mode is
> enabled. This functionality was already broken and is
> causing confusion.
>
> Signed-off-by: Mykola Lysenko <[e-mail]>
> ---

Works great! I've dropped the before test/subtest duplicated output of
test/subtest name, as it seems unnecessary in practice. I dropped few
lines of code that do that locally, as you suggested.

I also noticed a small memory leak, see comment below, please send a follow up.

>  tools/testing/selftests/bpf/test_progs.c | 640 +++++++++++++++++------
>  tools/testing/selftests/bpf/test_progs.h |  35 +-
>  2 files changed, 499 insertions(+), 176 deletions(-)
>

[...]

> +
> +static int dispatch_thread_read_log(int sock_fd, char **log_buf, size_t *log_cnt)
> +{
> +       FILE *log_fp = NULL;
> +
> +       log_fp = open_memstream(log_buf, log_cnt);
> +       if (!log_fp)
> +               return 1;
> +
> +       while (true) {
> +               struct msg msg;
> +
> +               if (read_prog_test_msg(sock_fd, &msg, MSG_TEST_LOG))

leaking log_fp here?

> +                       return 1;
> +
> +               fprintf(log_fp, "%s", msg.test_log.log_buf);
> +               if (msg.test_log.is_last)
> +                       break;
> +       }
> +       fclose(log_fp);
> +       log_fp = NULL;
> +       return 0;
> +}
> +

[...]

[e-mail] April 28, 2022, 2:10 a.m. UTC | #2

Hello:

This patch was applied to bpf/bpf-next.git (master)
by Andrii Nakryiko <[e-mail]>:

On Tue, 26 Apr 2022 21:13:53 -0700 you wrote:
> Implement per subtest log collection for both parallel
> and sequential test execution. This allows granular
> per-subtest error output in the 'All error logs' section.
> Add subtest log transfer into the protocol during the
> parallel test execution.
> 
> Move all test log printing logic into dump_test_log
> function. One exception is the output of test names when
> verbose printing is enabled. Move test name/result
> printing into separate functions to avoid repetition.
> 
> [...]

Here is the summary with links:
  - [v2,bpf-next] bpf/selftests: add granular subtest output for prog_test
    https://git.kernel.org/bpf/bpf-next/c/0925225956bb

You are awesome, thank you!

Mykola Lysenko April 28, 2022, 11:21 p.m. UTC | #3

> On Apr 27, 2022, at 3:38 PM, Andrii Nakryiko <[e-mail]> wrote:
> 
> On Tue, Apr 26, 2022 at 9:14 PM Mykola Lysenko <[e-mail]> wrote:
>> 
>> Implement per subtest log collection for both parallel
>> and sequential test execution. This allows granular
>> per-subtest error output in the 'All error logs' section.
>> Add subtest log transfer into the protocol during the
>> parallel test execution.
>> 
>> Move all test log printing logic into dump_test_log
>> function. One exception is the output of test names when
>> verbose printing is enabled. Move test name/result
>> printing into separate functions to avoid repetition.
>> 
>> Print all successful subtest results in the log. Print
>> only failed test logs when test does not have subtests.
>> Or only failed subtests' logs when test has subtests.
>> 
>> Disable 'All error logs' output when verbose mode is
>> enabled. This functionality was already broken and is
>> causing confusion.
>> 
>> Signed-off-by: Mykola Lysenko <[e-mail]>
>> ---
> 
> Works great! I've dropped the before test/subtest duplicated output of
> test/subtest name, as it seems unnecessary in practice. I dropped few
> lines of code that do that locally, as you suggested.
> 
> I also noticed a small memory leak, see comment below, please send a follow up.

Thanks a lot Andrii for the review!

I have sent a follow-up patch

> 
>> tools/testing/selftests/bpf/test_progs.c | 640 +++++++++++++++++------
>> tools/testing/selftests/bpf/test_progs.h | 35 +-
>> 2 files changed, 499 insertions(+), 176 deletions(-)
>> 
> 
> [...]
> 
>> +
>> +static int dispatch_thread_read_log(int sock_fd, char **log_buf, size_t *log_cnt)
>> +{
>> + FILE *log_fp = NULL;
>> +
>> + log_fp = open_memstream(log_buf, log_cnt);
>> + if (!log_fp)
>> + return 1;
>> +
>> + while (true) {
>> + struct msg msg;
>> +
>> + if (read_prog_test_msg(sock_fd, &msg, MSG_TEST_LOG))
> 
> leaking log_fp here?
> 
>> + return 1;
>> +
>> + fprintf(log_fp, "%s", msg.test_log.log_buf);
>> + if (msg.test_log.is_last)
>> + break;
>> + }
>> + fclose(log_fp);
>> + log_fp = NULL;
>> + return 0;
>> +}
>> +
> 
> [...]

Patch

diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index c536d1d29d57..84d9aa9276ba 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c
@@ -18,6 +18,91 @@ 
 #include <sys/socket.h>
 #include <sys/un.h>
 
+static bool verbose(void)
+{
+	return env.verbosity > VERBOSE_NONE;
+}
+
+static void stdio_hijack_init(char **log_buf, size_t *log_cnt)
+{
+#ifdef __GLIBC__
+	if (verbose() && env.worker_id == -1) {
+		/* nothing to do, output to stdout by default */
+		return;
+	}
+
+	fflush(stdout);
+	fflush(stderr);
+
+	stdout = open_memstream(log_buf, log_cnt);
+	if (!stdout) {
+		stdout = env.stdout;
+		perror("open_memstream");
+		return;
+	}
+
+	if (env.subtest_state)
+		env.subtest_state->stdout = stdout;
+	else
+		env.test_state->stdout = stdout;
+
+	stderr = stdout;
+#endif
+}
+
+static void stdio_hijack(char **log_buf, size_t *log_cnt)
+{
+#ifdef __GLIBC__
+	if (verbose() && env.worker_id == -1) {
+		/* nothing to do, output to stdout by default */
+		return;
+	}
+
+	env.stdout = stdout;
+	env.stderr = stderr;
+
+	stdio_hijack_init(log_buf, log_cnt);
+#endif
+}
+
+static void stdio_restore_cleanup(void)
+{
+#ifdef __GLIBC__
+	if (verbose() && env.worker_id == -1) {
+		/* nothing to do, output to stdout by default */
+		return;
+	}
+
+	fflush(stdout);
+
+	if (env.subtest_state) {
+		fclose(env.subtest_state->stdout);
+		stdout = env.test_state->stdout;
+		stderr = env.test_state->stdout;
+	} else {
+		fclose(env.test_state->stdout);
+	}
+#endif
+}
+
+static void stdio_restore(void)
+{
+#ifdef __GLIBC__
+	if (verbose() && env.worker_id == -1) {
+		/* nothing to do, output to stdout by default */
+		return;
+	}
+
+	if (stdout == env.stdout)
+		return;
+
+	stdio_restore_cleanup();
+
+	stdout = env.stdout;
+	stderr = env.stderr;
+#endif
+}
+
 /* Adapted from perf/util/string.c */
 static bool glob_match(const char *str, const char *pat)
 {
@@ -130,30 +215,96 @@  static bool should_run_subtest(struct test_selector *sel,
 	return subtest_num < subtest_sel->num_set_len && subtest_sel->num_set[subtest_num];
 }
 
+static char *test_result(bool failed, bool skipped)
+{
+	return failed ? "FAIL" : (skipped ? "SKIP" : "OK");
+}
+
+static void print_test_log(char *log_buf, size_t log_cnt)
+{
+	log_buf[log_cnt] = '\0';
+	fprintf(env.stdout, "%s", log_buf);
+	if (log_buf[log_cnt - 1] != '\n')
+		fprintf(env.stdout, "\n");
+}
+
+static void print_test_name(int test_num, const char *test_name, char *result)
+{
+	fprintf(env.stdout, "#%-9d %s", test_num, test_name);
+
+	if (result)
+		fprintf(env.stdout, ":%s", result);
+
+	fprintf(env.stdout, "\n");
+}
+
+static void print_subtest_name(int test_num, int subtest_num,
+			       const char *test_name, char *subtest_name,
+			       char *result)
+{
+	fprintf(env.stdout, "#%-3d/%-5d %s/%s",
+		test_num, subtest_num,
+		test_name, subtest_name);
+
+	if (result)
+		fprintf(env.stdout, ":%s", result);
+
+	fprintf(env.stdout, "\n");
+}
+
 static void dump_test_log(const struct prog_test_def *test,
 			  const struct test_state *test_state,
-			  bool force_failed)
+			  bool skip_ok_subtests,
+			  bool par_exec_result)
 {
-	bool failed = test_state->error_cnt > 0 || force_failed;
+	bool test_failed = test_state->error_cnt > 0;
+	bool force_log = test_state->force_log;
+	bool print_test = verbose() || force_log || test_failed;
+	int i;
+	struct subtest_state *subtest_state;
+	bool subtest_failed;
+	bool print_subtest;
 
-	/* worker always holds log */
+	/* we do not print anything in the worker thread */
 	if (env.worker_id != -1)
 		return;
 
-	fflush(stdout); /* exports test_state->log_buf & test_state->log_cnt */
+	/* there is nothing to print when verbose log is used and execution
+	 * is not in parallel mode
+	 */
+	if (verbose() && !par_exec_result)
+		return;
+
+	if (test_state->subtest_num || print_test)
+		print_test_name(test->test_num, test->test_name, NULL);
+
+	if (test_state->log_cnt && print_test)
+		print_test_log(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"));
+	for (i = 0; i < test_state->subtest_num; i++) {
+		subtest_state = &test_state->subtest_states[i];
+		subtest_failed = subtest_state->error_cnt;
+		print_subtest = verbose() || force_log || subtest_failed;
 
-	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");
+		if (skip_ok_subtests && !subtest_failed)
+			continue;
+
+		if (subtest_state->log_cnt && print_subtest) {
+			print_subtest_name(test->test_num, i + 1,
+					   test->test_name, subtest_state->name,
+					   NULL);
+			print_test_log(subtest_state->log_buf,
+				       subtest_state->log_cnt);
 		}
+
+		print_subtest_name(test->test_num, i + 1,
+				   test->test_name, subtest_state->name,
+				   test_result(subtest_state->error_cnt,
+					       subtest_state->skipped));
 	}
+
+	print_test_name(test->test_num, test->test_name,
+			test_result(test_failed, test_state->skip_cnt));
 }
 
 static void stdio_restore(void);
@@ -205,35 +356,50 @@  static void restore_netns(void)
 void test__end_subtest(void)
 {
 	struct prog_test_def *test = env.test;
-	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, state->subtest_num, test->test_name, state->subtest_name,
-	       sub_error_cnt ? "FAIL" : (state->subtest_skip_cnt ? "SKIP" : "OK"));
-
-	if (sub_error_cnt == 0) {
-		if (state->subtest_skip_cnt == 0) {
-			state->sub_succ_cnt++;
-		} else {
-			state->subtest_skip_cnt = 0;
-			state->skip_cnt++;
-		}
+	struct test_state *test_state = env.test_state;
+	struct subtest_state *subtest_state = env.subtest_state;
+
+	if (subtest_state->error_cnt) {
+		test_state->error_cnt++;
+	} else {
+		if (!subtest_state->skipped)
+			test_state->sub_succ_cnt++;
+		else
+			test_state->skip_cnt++;
 	}
 
-	free(state->subtest_name);
-	state->subtest_name = NULL;
+	if (verbose() && !env.workers)
+		print_subtest_name(test->test_num, test_state->subtest_num,
+				   test->test_name, subtest_state->name,
+				   test_result(subtest_state->error_cnt,
+					       subtest_state->skipped));
+
+	stdio_restore_cleanup();
+	env.subtest_state = NULL;
 }
 
 bool test__start_subtest(const char *subtest_name)
 {
 	struct prog_test_def *test = env.test;
 	struct test_state *state = env.test_state;
+	struct subtest_state *subtest_state;
+	size_t sub_state_size = sizeof(*subtest_state);
 
-	if (state->subtest_name)
+	if (env.subtest_state)
 		test__end_subtest();
 
 	state->subtest_num++;
+	state->subtest_states =
+		realloc(state->subtest_states,
+			state->subtest_num * sub_state_size);
+	if (!state->subtest_states) {
+		fprintf(stderr, "Not enough memory to allocate subtest result\n");
+		return false;
+	}
+
+	subtest_state = &state->subtest_states[state->subtest_num - 1];
+
+	memset(subtest_state, 0, sub_state_size);
 
 	if (!subtest_name || !subtest_name[0]) {
 		fprintf(env.stderr,
@@ -242,21 +408,30 @@  bool test__start_subtest(const char *subtest_name)
 		return false;
 	}
 
+	subtest_state->name = strdup(subtest_name);
+	if (!subtest_state->name) {
+		fprintf(env.stderr,
+			"Subtest #%d: failed to copy subtest name!\n",
+			state->subtest_num);
+		return false;
+	}
+
 	if (!should_run_subtest(&env.test_selector,
 				&env.subtest_selector,
 				state->subtest_num,
 				test->test_name,
-				subtest_name))
-		return false;
-
-	state->subtest_name = strdup(subtest_name);
-	if (!state->subtest_name) {
-		fprintf(env.stderr,
-			"Subtest #%d: failed to copy subtest name!\n",
-			state->subtest_num);
+				subtest_name)) {
+		subtest_state->skipped = true;
 		return false;
 	}
-	state->old_error_cnt = state->error_cnt;
+
+	env.subtest_state = subtest_state;
+	stdio_hijack_init(&subtest_state->log_buf, &subtest_state->log_cnt);
+
+	if (verbose() && !env.workers)
+		print_subtest_name(test->test_num, state->subtest_num,
+				   test->test_name, subtest_state->name,
+				   NULL);
 
 	return true;
 }
@@ -268,15 +443,18 @@  void test__force_log(void)
 
 void test__skip(void)
 {
-	if (env.test_state->subtest_name)
-		env.test_state->subtest_skip_cnt++;
+	if (env.subtest_state)
+		env.subtest_state->skipped = true;
 	else
 		env.test_state->skip_cnt++;
 }
 
 void test__fail(void)
 {
-	env.test_state->error_cnt++;
+	if (env.subtest_state)
+		env.subtest_state->error_cnt++;
+	else
+		env.test_state->error_cnt++;
 }
 
 int test__join_cgroup(const char *path)
@@ -455,14 +633,14 @@  static void unload_bpf_testmod(void)
 		fprintf(env.stderr, "Failed to trigger kernel-side RCU sync!\n");
 	if (delete_module("bpf_testmod", 0)) {
 		if (errno == ENOENT) {
-			if (env.verbosity > VERBOSE_NONE)
+			if (verbose())
 				fprintf(stdout, "bpf_testmod.ko is already unloaded.\n");
 			return;
 		}
 		fprintf(env.stderr, "Failed to unload bpf_testmod.ko from kernel: %d\n", -errno);
 		return;
 	}
-	if (env.verbosity > VERBOSE_NONE)
+	if (verbose())
 		fprintf(stdout, "Successfully unloaded bpf_testmod.ko.\n");
 }
 
@@ -473,7 +651,7 @@  static int load_bpf_testmod(void)
 	/* ensure previous instance of the module is unloaded */
 	unload_bpf_testmod();
 
-	if (env.verbosity > VERBOSE_NONE)
+	if (verbose())
 		fprintf(stdout, "Loading bpf_testmod.ko...\n");
 
 	fd = open("bpf_testmod.ko", O_RDONLY);
@@ -488,7 +666,7 @@  static int load_bpf_testmod(void)
 	}
 	close(fd);
 
-	if (env.verbosity > VERBOSE_NONE)
+	if (verbose())
 		fprintf(stdout, "Successfully loaded bpf_testmod.ko.\n");
 	return 0;
 }
@@ -655,7 +833,7 @@  static error_t parse_arg(int key, char *arg, struct argp_state *state)
 			}
 		}
 
-		if (env->verbosity > VERBOSE_NONE) {
+		if (verbose()) {
 			if (setenv("SELFTESTS_VERBOSE", "1", 1) == -1) {
 				fprintf(stderr,
 					"Unable to setenv SELFTESTS_VERBOSE=1 (errno=%d)",
@@ -696,44 +874,6 @@  static error_t parse_arg(int key, char *arg, struct argp_state *state)
 	return 0;
 }
 
-static void stdio_hijack(char **log_buf, size_t *log_cnt)
-{
-#ifdef __GLIBC__
-	env.stdout = stdout;
-	env.stderr = stderr;
-
-	if (env.verbosity > VERBOSE_NONE && env.worker_id == -1) {
-		/* nothing to do, output to stdout by default */
-		return;
-	}
-
-	/* stdout and stderr -> buffer */
-	fflush(stdout);
-
-	stdout = open_memstream(log_buf, log_cnt);
-	if (!stdout) {
-		stdout = env.stdout;
-		perror("open_memstream");
-		return;
-	}
-
-	stderr = stdout;
-#endif
-}
-
-static void stdio_restore(void)
-{
-#ifdef __GLIBC__
-	if (stdout == env.stdout)
-		return;
-
-	fclose(stdout);
-
-	stdout = env.stdout;
-	stderr = env.stderr;
-#endif
-}
-
 /*
  * Determine if test_progs is running as a "flavored" test runner and switch
  * into corresponding sub-directory to load correct BPF objects.
@@ -759,7 +899,7 @@  int cd_flavor_subdir(const char *exec_name)
 	if (!flavor)
 		return 0;
 	flavor++;
-	if (env.verbosity > VERBOSE_NONE)
+	if (verbose())
 		fprintf(stdout,	"Switching to flavor '%s' subdirectory...\n", flavor);
 
 	return chdir(flavor);
@@ -812,8 +952,10 @@  void crash_handler(int signum)
 
 	sz = backtrace(bt, ARRAY_SIZE(bt));
 
-	if (env.test)
-		dump_test_log(env.test, env.test_state, true);
+	if (env.test) {
+		env.test_state->error_cnt++;
+		dump_test_log(env.test, env.test_state, true, false);
+	}
 	if (env.stdout)
 		stdio_restore();
 	if (env.worker_id != -1)
@@ -839,13 +981,18 @@  static inline const char *str_msg(const struct msg *msg, char *buf)
 {
 	switch (msg->type) {
 	case MSG_DO_TEST:
-		sprintf(buf, "MSG_DO_TEST %d", msg->do_test.test_num);
+		sprintf(buf, "MSG_DO_TEST %d", msg->do_test.num);
 		break;
 	case MSG_TEST_DONE:
 		sprintf(buf, "MSG_TEST_DONE %d (log: %d)",
-			msg->test_done.test_num,
+			msg->test_done.num,
 			msg->test_done.have_log);
 		break;
+	case MSG_SUBTEST_DONE:
+		sprintf(buf, "MSG_SUBTEST_DONE %d (log: %d)",
+			msg->subtest_done.num,
+			msg->subtest_done.have_log);
+		break;
 	case MSG_TEST_LOG:
 		sprintf(buf, "MSG_TEST_LOG (cnt: %ld, last: %d)",
 			strlen(msg->test_log.log_buf),
@@ -895,18 +1042,23 @@  static void run_one_test(int test_num)
 
 	stdio_hijack(&state->log_buf, &state->log_cnt);
 
+	if (verbose() && env.worker_id == -1)
+		print_test_name(test_num + 1, test->test_name, NULL);
+
 	if (test->run_test)
 		test->run_test();
 	else if (test->run_serial_test)
 		test->run_serial_test();
 
 	/* ensure last sub-test is finalized properly */
-	if (state->subtest_name)
+	if (env.subtest_state)
 		test__end_subtest();
 
 	state->tested = true;
 
-	dump_test_log(test, state, false);
+	if (verbose() && env.worker_id == -1)
+		print_test_name(test_num + 1, test->test_name,
+				test_result(state->error_cnt, state->skip_cnt));
 
 	reset_affinity();
 	restore_netns();
@@ -914,6 +1066,8 @@  static void run_one_test(int test_num)
 		cleanup_cgroup_environment();
 
 	stdio_restore();
+
+	dump_test_log(test, state, false, false);
 }
 
 struct dispatch_data {
@@ -921,6 +1075,73 @@  struct dispatch_data {
 	int sock_fd;
 };
 
+static int read_prog_test_msg(int sock_fd, struct msg *msg, enum msg_type type)
+{
+	if (recv_message(sock_fd, msg) < 0)
+		return 1;
+
+	if (msg->type != type) {
+		printf("%s: unexpected message type %d. expected %d\n", __func__, msg->type, type);
+		return 1;
+	}
+
+	return 0;
+}
+
+static int dispatch_thread_read_log(int sock_fd, char **log_buf, size_t *log_cnt)
+{
+	FILE *log_fp = NULL;
+
+	log_fp = open_memstream(log_buf, log_cnt);
+	if (!log_fp)
+		return 1;
+
+	while (true) {
+		struct msg msg;
+
+		if (read_prog_test_msg(sock_fd, &msg, MSG_TEST_LOG))
+			return 1;
+
+		fprintf(log_fp, "%s", msg.test_log.log_buf);
+		if (msg.test_log.is_last)
+			break;
+	}
+	fclose(log_fp);
+	log_fp = NULL;
+	return 0;
+}
+
+static int dispatch_thread_send_subtests(int sock_fd, struct test_state *state)
+{
+	struct msg msg;
+	struct subtest_state *subtest_state;
+	int subtest_num = state->subtest_num;
+
+	state->subtest_states = malloc(subtest_num * sizeof(*subtest_state));
+
+	for (int i = 0; i < subtest_num; i++) {
+		subtest_state = &state->subtest_states[i];
+
+		memset(subtest_state, 0, sizeof(*subtest_state));
+
+		if (read_prog_test_msg(sock_fd, &msg, MSG_SUBTEST_DONE))
+			return 1;
+
+		subtest_state->name = strdup(msg.subtest_done.name);
+		subtest_state->error_cnt = msg.subtest_done.error_cnt;
+		subtest_state->skipped = msg.subtest_done.skipped;
+
+		/* collect all logs */
+		if (msg.subtest_done.have_log)
+			if (dispatch_thread_read_log(sock_fd,
+						     &subtest_state->log_buf,
+						     &subtest_state->log_cnt))
+				return 1;
+	}
+
+	return 0;
+}
+
 static void *dispatch_thread(void *ctx)
 {
 	struct dispatch_data *data = ctx;
@@ -957,8 +1178,9 @@  static void *dispatch_thread(void *ctx)
 		{
 			struct msg msg_do_test;
 
+			memset(&msg_do_test, 0, sizeof(msg_do_test));
 			msg_do_test.type = MSG_DO_TEST;
-			msg_do_test.do_test.test_num = test_to_run;
+			msg_do_test.do_test.num = test_to_run;
 			if (send_message(sock_fd, &msg_do_test) < 0) {
 				perror("Fail to send command");
 				goto done;
@@ -967,49 +1189,39 @@  static void *dispatch_thread(void *ctx)
 		}
 
 		/* wait for test done */
-		{
-			int err;
-			struct msg msg_test_done;
+		do {
+			struct msg msg;
 
-			err = recv_message(sock_fd, &msg_test_done);
-			if (err < 0)
+			if (read_prog_test_msg(sock_fd, &msg, MSG_TEST_DONE))
 				goto error;
-			if (msg_test_done.type != MSG_TEST_DONE)
-				goto error;
-			if (test_to_run != msg_test_done.test_done.test_num)
+			if (test_to_run != msg.test_done.num)
 				goto error;
 
 			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;
+			state->error_cnt = msg.test_done.error_cnt;
+			state->skip_cnt = msg.test_done.skip_cnt;
+			state->sub_succ_cnt = msg.test_done.sub_succ_cnt;
+			state->subtest_num = msg.test_done.subtest_num;
 
 			/* collect all logs */
-			if (msg_test_done.test_done.have_log) {
-				log_fp = open_memstream(&state->log_buf, &state->log_cnt);
-				if (!log_fp)
+			if (msg.test_done.have_log) {
+				if (dispatch_thread_read_log(sock_fd,
+							     &state->log_buf,
+							     &state->log_cnt))
 					goto error;
+			}
 
-				while (true) {
-					struct msg msg_log;
-
-					if (recv_message(sock_fd, &msg_log) < 0)
-						goto error;
-					if (msg_log.type != MSG_TEST_LOG)
-						goto error;
+			/* collect all subtests and subtest logs */
+			if (!state->subtest_num)
+				break;
 
-					fprintf(log_fp, "%s", msg_log.test_log.log_buf);
-					if (msg_log.test_log.is_last)
-						break;
-				}
-				fclose(log_fp);
-				log_fp = NULL;
-			}
-		} /* wait for test done */
+			if (dispatch_thread_send_subtests(sock_fd, state))
+				goto error;
+		} while (false);
 
 		pthread_mutex_lock(&stdout_output_lock);
-		dump_test_log(test, state, false);
+		dump_test_log(test, state, false, true);
 		pthread_mutex_unlock(&stdout_output_lock);
 	} /* while (true) */
 error:
@@ -1052,18 +1264,24 @@  static void calculate_summary_and_print_errors(struct test_env *env)
 			succ_cnt++;
 	}
 
-	if (fail_cnt)
+	/*
+	 * We only print error logs summary when there are failed tests and
+	 * verbose mode is not enabled. Otherwise, results may be incosistent.
+	 *
+	 */
+	if (!verbose() && fail_cnt) {
 		printf("\nAll error logs:\n");
 
-	/* print error logs again */
-	for (i = 0; i < prog_test_cnt; i++) {
-		struct prog_test_def *test = &prog_test_defs[i];
-		struct test_state *state = &test_states[i];
+		/* print error logs again */
+		for (i = 0; i < prog_test_cnt; i++) {
+			struct prog_test_def *test = &prog_test_defs[i];
+			struct test_state *state = &test_states[i];
 
-		if (!state->tested || !state->error_cnt)
-			continue;
+			if (!state->tested || !state->error_cnt)
+				continue;
 
-		dump_test_log(test, state, true);
+			dump_test_log(test, state, true, true);
+		}
 	}
 
 	printf("Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
@@ -1154,6 +1372,90 @@  static void server_main(void)
 	}
 }
 
+static void worker_main_send_log(int sock, char *log_buf, size_t log_cnt)
+{
+	char *src;
+	size_t slen;
+
+	src = log_buf;
+	slen = log_cnt;
+	while (slen) {
+		struct msg msg_log;
+		char *dest;
+		size_t len;
+
+		memset(&msg_log, 0, sizeof(msg_log));
+		msg_log.type = MSG_TEST_LOG;
+		dest = msg_log.test_log.log_buf;
+		len = slen >= MAX_LOG_TRUNK_SIZE ? MAX_LOG_TRUNK_SIZE : slen;
+		memcpy(dest, src, len);
+
+		src += len;
+		slen -= len;
+		if (!slen)
+			msg_log.test_log.is_last = true;
+
+		assert(send_message(sock, &msg_log) >= 0);
+	}
+}
+
+static void free_subtest_state(struct subtest_state *state)
+{
+	if (state->log_buf) {
+		free(state->log_buf);
+		state->log_buf = NULL;
+		state->log_cnt = 0;
+	}
+	free(state->name);
+	state->name = NULL;
+}
+
+static int worker_main_send_subtests(int sock, struct test_state *state)
+{
+	int i, result = 0;
+	struct msg msg;
+	struct subtest_state *subtest_state;
+
+	memset(&msg, 0, sizeof(msg));
+	msg.type = MSG_SUBTEST_DONE;
+
+	for (i = 0; i < state->subtest_num; i++) {
+		subtest_state = &state->subtest_states[i];
+
+		msg.subtest_done.num = i;
+
+		strncpy(msg.subtest_done.name, subtest_state->name, MAX_SUBTEST_NAME);
+
+		msg.subtest_done.error_cnt = subtest_state->error_cnt;
+		msg.subtest_done.skipped = subtest_state->skipped;
+		msg.subtest_done.have_log = false;
+
+		if (verbose() || state->force_log || subtest_state->error_cnt) {
+			if (subtest_state->log_cnt)
+				msg.subtest_done.have_log = true;
+		}
+
+		if (send_message(sock, &msg) < 0) {
+			perror("Fail to send message done");
+			result = 1;
+			goto out;
+		}
+
+		/* send logs */
+		if (msg.subtest_done.have_log)
+			worker_main_send_log(sock, subtest_state->log_buf, subtest_state->log_cnt);
+
+		free_subtest_state(subtest_state);
+		free(subtest_state->name);
+	}
+
+out:
+	for (; i < state->subtest_num; i++)
+		free_subtest_state(&state->subtest_states[i]);
+	free(state->subtest_states);
+	return result;
+}
+
 static int worker_main(int sock)
 {
 	save_netns();
@@ -1172,10 +1474,10 @@  static int worker_main(int sock)
 					env.worker_id);
 			goto out;
 		case MSG_DO_TEST: {
-			int test_to_run = msg.do_test.test_num;
+			int test_to_run = msg.do_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;
+			struct msg msg;
 
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s running.\n",
@@ -1185,54 +1487,38 @@  static int worker_main(int sock)
 
 			run_one_test(test_to_run);
 
-			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 = 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;
+			memset(&msg, 0, sizeof(msg));
+			msg.type = MSG_TEST_DONE;
+			msg.test_done.num = test_to_run;
+			msg.test_done.error_cnt = state->error_cnt;
+			msg.test_done.skip_cnt = state->skip_cnt;
+			msg.test_done.sub_succ_cnt = state->sub_succ_cnt;
+			msg.test_done.subtest_num = state->subtest_num;
+			msg.test_done.have_log = false;
 
-			if (env.verbosity > VERBOSE_NONE || state->force_log || state->error_cnt) {
+			if (verbose() || state->force_log || state->error_cnt) {
 				if (state->log_cnt)
-					msg_done.test_done.have_log = true;
+					msg.test_done.have_log = true;
 			}
-			if (send_message(sock, &msg_done) < 0) {
+			if (send_message(sock, &msg) < 0) {
 				perror("Fail to send message done");
 				goto out;
 			}
 
 			/* send logs */
-			if (msg_done.test_done.have_log) {
-				char *src;
-				size_t slen;
-
-				src = state->log_buf;
-				slen = state->log_cnt;
-				while (slen) {
-					struct msg msg_log;
-					char *dest;
-					size_t len;
-
-					memset(&msg_log, 0, sizeof(msg_log));
-					msg_log.type = MSG_TEST_LOG;
-					dest = msg_log.test_log.log_buf;
-					len = slen >= MAX_LOG_TRUNK_SIZE ? MAX_LOG_TRUNK_SIZE : slen;
-					memcpy(dest, src, len);
-
-					src += len;
-					slen -= len;
-					if (!slen)
-						msg_log.test_log.is_last = true;
-
-					assert(send_message(sock, &msg_log) >= 0);
-				}
-			}
+			if (msg.test_done.have_log)
+				worker_main_send_log(sock, state->log_buf, state->log_cnt);
+
 			if (state->log_buf) {
 				free(state->log_buf);
 				state->log_buf = NULL;
 				state->log_cnt = 0;
 			}
+
+			if (state->subtest_num)
+				if (worker_main_send_subtests(sock, state))
+					goto out;
+
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s done.\n",
 					env.worker_id,
@@ -1250,6 +1536,23 @@  static int worker_main(int sock)
 	return 0;
 }
 
+static void free_test_states(void)
+{
+	int i, j;
+
+	for (i = 0; i < ARRAY_SIZE(prog_test_defs); i++) {
+		struct test_state *test_state = &test_states[i];
+
+		for (j = 0; j < test_state->subtest_num; j++)
+			free_subtest_state(&test_state->subtest_states[j]);
+
+		free(test_state->subtest_states);
+		free(test_state->log_buf);
+		test_state->subtest_states = NULL;
+		test_state->log_buf = NULL;
+	}
+}
+
 int main(int argc, char **argv)
 {
 	static const struct argp argp = {
@@ -1396,6 +1699,7 @@  int main(int argc, char **argv)
 		unload_bpf_testmod();
 
 	free_test_selector(&env.test_selector);
+	free_test_states();
 
 	if (env.succ_cnt + env.fail_cnt + env.skip_cnt == 0)
 		return EXIT_NO_TEST;
diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
index 0a102ce460d6..18262077fdeb 100644
--- a/tools/testing/selftests/bpf/test_progs.h
+++ b/tools/testing/selftests/bpf/test_progs.h
@@ -64,23 +64,31 @@  struct test_selector {
 	int num_set_len;
 };
 
+struct subtest_state {
+	char *name;
+	size_t log_cnt;
+	char *log_buf;
+	int error_cnt;
+	bool skipped;
+
+	FILE *stdout;
+};
+
 struct test_state {
 	bool tested;
 	bool force_log;
 
 	int error_cnt;
 	int skip_cnt;
-	int subtest_skip_cnt;
 	int sub_succ_cnt;
 
-	char *subtest_name;
+	struct subtest_state *subtest_states;
 	int subtest_num;
 
-	/* store counts before subtest started */
-	int old_error_cnt;
-
 	size_t log_cnt;
 	char *log_buf;
+
+	FILE *stdout;
 };
 
 struct test_env {
@@ -96,7 +104,8 @@  struct test_env {
 	bool list_test_names;
 
 	struct prog_test_def *test; /* current running test */
-	struct test_state *test_state; /* current running test result */
+	struct test_state *test_state; /* current running test state */
+	struct subtest_state *subtest_state; /* current running subtest state */
 
 	FILE *stdout;
 	FILE *stderr;
@@ -116,29 +125,39 @@  struct test_env {
 };
 
 #define MAX_LOG_TRUNK_SIZE 8192
+#define MAX_SUBTEST_NAME 1024
 enum msg_type {
 	MSG_DO_TEST = 0,
 	MSG_TEST_DONE = 1,
 	MSG_TEST_LOG = 2,
+	MSG_SUBTEST_DONE = 3,
 	MSG_EXIT = 255,
 };
 struct msg {
 	enum msg_type type;
 	union {
 		struct {
-			int test_num;
+			int num;
 		} do_test;
 		struct {
-			int test_num;
+			int num;
 			int sub_succ_cnt;
 			int error_cnt;
 			int skip_cnt;
 			bool have_log;
+			int subtest_num;
 		} test_done;
 		struct {
 			char log_buf[MAX_LOG_TRUNK_SIZE + 1];
 			bool is_last;
 		} test_log;
+		struct {
+			int num;
+			char name[MAX_SUBTEST_NAME + 1];
+			int error_cnt;
+			bool skipped;
+			bool have_log;
+		} subtest_done;
 	};
 };