On Mon, Oct 25, 2021 at 9:09 PM Andrii Nakryiko
<andrii.nakryiko@xxxxxxxxx> wrote:
>
> On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@xxxxxx> wrote:
> >
> > From: Yucong Sun <sunyucong@xxxxxxxxx>
> >
> > This patch restores behavior that prints one status line for each
> > subtest executed. It works in both serial mode and parallel mode, and
> > all verbosity settings.
> >
> > The logic around IO hijacking could use some more simplification in the
> > future.
> >
>
> This feels like a big hack, not a proper solution. What if we extend
> MSG_TEST_DONE to signal also sub-test completion (along with subtest
> logs)? Would that work better and result in cleaner logic?
I think the current solution is actually cleaner. Yes we could add
fields in task struct to record each subtest's name and status and
generate the status line separately, but it will only work in
situations where all tests pass.
When there is an error, we do want to mix the status line with the
actual stdout logs, which we won't be able to do afterwards.
Besides, we will still need to implement separate logic in 3 places
(serial mode, parallel mode in worker process, and serial part of
parallel mode execution). Having two copies of stdout logs is actually
not that bad.
>
> > Signed-off-by: Yucong Sun <sunyucong@xxxxxxxxx>
> > ---
> > tools/testing/selftests/bpf/test_progs.c | 56 +++++++++++++++++++-----
> > tools/testing/selftests/bpf/test_progs.h | 4 ++
> > 2 files changed, 50 insertions(+), 10 deletions(-)
> >
> > diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
> > index 1f4a48566991..ff4598126f9d 100644
> > --- a/tools/testing/selftests/bpf/test_progs.c
> > +++ b/tools/testing/selftests/bpf/test_progs.c
> > @@ -100,6 +100,18 @@ static bool should_run(struct test_selector *sel, int num, const char *name)
> > return num < sel->num_set_len && sel->num_set[num];
> > }
> >
> > +static void dump_subtest_status(bool display) {
>
> please run checkpatch.pl
>
> > + fflush(env.subtest_status_fd);
> > + if (display) {
> > + if (env.subtest_status_cnt) {
> > + env.subtest_status_buf[env.subtest_status_cnt] = '\0';
> > + fputs(env.subtest_status_buf, stdout);
> > + }
> > + }
> > + rewind(env.subtest_status_fd);
> > + fflush(env.subtest_status_fd);
> > +}
> > +
> > static void dump_test_log(const struct prog_test_def *test, bool failed)
> > {
> > if (stdout == env.stdout)
> > @@ -112,12 +124,17 @@ static void dump_test_log(const struct prog_test_def *test, bool failed)
> > fflush(stdout); /* exports env.log_buf & env.log_cnt */
> >
> > 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')
> > - fprintf(env.stdout, "\n");
> > - }
> > + dump_subtest_status(false);
> > + } else {
> > + rewind(stdout);
> > + dump_subtest_status(true);
> > + fflush(stdout);
> > + }
> > + 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')
> > + fprintf(env.stdout, "\n");
> > }
> > }
> >
> > @@ -183,7 +200,12 @@ void test__end_subtest(void)
> >
> > dump_test_log(test, sub_error_cnt);
> >
> > + // Print two copies here, one as part of full logs, another one will
> > + // only be used if there is no need to show full logs.
>
> C++ style comments
>
> > 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"));
> > + fprintf(env.subtest_status_fd, "#%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"));
> >
> > @@ -1250,6 +1272,15 @@ static int worker_main(int sock)
> >
> > run_one_test(test_to_run);
> >
> > + // discard logs if we don't need them
>
> C++ style comment
>
> > + if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
> > + dump_subtest_status(false);
> > + } else {
> > + rewind(stdout);
> > + dump_subtest_status(true);
> > + fflush(stdout);
> > + }
> > +
> > stdio_restore();
> >
> > memset(&msg_done, 0, sizeof(msg_done));
> > @@ -1260,10 +1291,9 @@ static int worker_main(int sock)
> > msg_done.test_done.sub_succ_cnt = test->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)
> > - msg_done.test_done.have_log = true;
> > - }
> > + if (env.log_cnt)
> > + msg_done.test_done.have_log = true;
> > +
> > if (send_message(sock, &msg_done) < 0) {
> > perror("Fail to send message done");
> > goto out;
> > @@ -1357,6 +1387,12 @@ int main(int argc, char **argv)
> >
> > env.stdout = stdout;
> > env.stderr = stderr;
> > + env.subtest_status_fd = open_memstream(
>
> extremely misleading name, it's not an FD at all
it is indeed a file descriptor, isn't it? What's a better name for it?
>
> > + &env.subtest_status_buf, &env.subtest_status_cnt);
> > + if (!env.subtest_status_fd) {
> > + perror("Failed to setup env.subtest_status_fd");
> > + exit(EXIT_ERR_SETUP_INFRA);
> > + }
> >
> > env.has_testmod = true;
> > if (!env.list_test_names && load_bpf_testmod()) {
> > diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> > index 93c1ff705533..a564215a63b1 100644
> > --- a/tools/testing/selftests/bpf/test_progs.h
> > +++ b/tools/testing/selftests/bpf/test_progs.h
> > @@ -89,6 +89,10 @@ struct test_env {
> > pid_t *worker_pids; /* array of worker pids */
> > int *worker_socks; /* array of worker socks */
> > int *worker_current_test; /* array of current running test for each worker */
> > +
> > + FILE* subtest_status_fd; /* fd for printing status line for subtests */
> > + char *subtest_status_buf; /* buffer for subtests status */
> > + size_t subtest_status_cnt;
> > };
> >
> > #define MAX_LOG_TRUNK_SIZE 8192
> > --
> > 2.30.2
> >
