Re: [PATCH bpf-next v4 1/3] selftests/bpf: test_progs: switch to open_memstream

[Stanislav Fomichev <sdf@fomichev.me>]

On 08/06, Andrii Nakryiko wrote:
> On Tue, Aug 6, 2019 at 10:19 AM Stanislav Fomichev <sdf@google.com> wrote:
> >
> > Use open_memstream to override stdout during test execution.
> > The copy of the original stdout is held in env.stdout and used
> > to print subtest info and dump failed log.
> >
> > test_{v,}printf are now simple wrappers around stdout and will be
> > removed in the next patch.
> >
> > v4:
> > * one field per line for stdout/stderr (Andrii Nakryiko)
> >
> > v3:
> > * don't do strlen over log_buf, log_cnt has it already (Andrii Nakryiko)
> >
> > v2:
> > * add ifdef __GLIBC__ around open_memstream (maybe pointless since
> >   we already depend on glibc for argp_parse)
> > * hijack stderr as well (Andrii Nakryiko)
> > * don't hijack for every test, do it once (Andrii Nakryiko)
> > * log_cap -> log_size (Andrii Nakryiko)
> > * do fseeko in a proper place (Andrii Nakryiko)
> > * check open_memstream returned value (Andrii Nakryiko)
> >
> > Cc: Andrii Nakryiko <andriin@fb.com>
> > Acked-by: Andrii Nakryiko <andriin@fb.com>
> > Signed-off-by: Stanislav Fomichev <sdf@google.com>
> > ---
> >  tools/testing/selftests/bpf/test_progs.c | 115 ++++++++++++-----------
> >  tools/testing/selftests/bpf/test_progs.h |   3 +-
> >  2 files changed, 62 insertions(+), 56 deletions(-)
> >
> > diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
> > index db00196c8315..9556439c607c 100644
> > --- a/tools/testing/selftests/bpf/test_progs.c
> > +++ b/tools/testing/selftests/bpf/test_progs.c
> > @@ -40,14 +40,20 @@ static bool should_run(struct test_selector *sel, int num, const char *name)
> >
> >  static void dump_test_log(const struct prog_test_def *test, bool failed)
> >  {
> > +       if (stdout == env.stdout)
> > +               return;
> > +
> > +       fflush(stdout); /* exports env.log_buf & env.log_cnt */
> > +
> >         if (env.verbose || test->force_log || failed) {
> >                 if (env.log_cnt) {
> > -                       fprintf(stdout, "%s", env.log_buf);
> > +                       fprintf(env.stdout, "%s", env.log_buf);
> >                         if (env.log_buf[env.log_cnt - 1] != '\n')
> > -                               fprintf(stdout, "\n");
> > +                               fprintf(env.stdout, "\n");
> >                 }
> >         }
> > -       env.log_cnt = 0;
> > +
> > +       fseeko(stdout, 0, SEEK_SET); /* rewind */
> >  }
> >
> >  void test__end_subtest()
> > @@ -62,7 +68,7 @@ void test__end_subtest()
> >
> >         dump_test_log(test, sub_error_cnt);
> >
> > -       printf("#%d/%d %s:%s\n",
> > +       fprintf(env.stdout, "#%d/%d %s:%s\n",
> >                test->test_num, test->subtest_num,
> >                test->subtest_name, sub_error_cnt ? "FAIL" : "OK");
> >  }
> > @@ -79,7 +85,8 @@ bool test__start_subtest(const char *name)
> >         test->subtest_num++;
> >
> >         if (!name || !name[0]) {
> > -               fprintf(stderr, "Subtest #%d didn't provide sub-test name!\n",
> > +               fprintf(env.stderr,
> > +                       "Subtest #%d didn't provide sub-test name!\n",
> >                         test->subtest_num);
> >                 return false;
> >         }
> > @@ -100,53 +107,7 @@ void test__force_log() {
> >
> >  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;
> > +       vprintf(fmt, args);
> >  }
> >
> >  void test__printf(const char *fmt, ...)
> > @@ -477,6 +438,48 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state)
> >         return 0;
> >  }
> >
> > +static void stdio_hijack(void)
> > +{
> > +#ifdef __GLIBC__
> > +       if (env.verbose || (env.test && env.test->force_log)) {
> 
> I just also realized that you don't need `(env.test &&
> env.test->force_log)` test. We hijack stdout/stderr before env.test is
> even set, so this does nothing anyways. Plus, force_log can be set in
> the middle of test/sub-test, yet we hijack stdout just once (or even
> if per-test), so it's still going to be "racy". Let's buffer output
> (unless it's env.verbose, which is important to not buffer because
> some tests will have huge output, when failing, so this allows to
> bypass using tons of memory for those, when debugging) and dump at the
> end.
Makes sense, will drop this test and resubmit along with a fix for '-v'
that Alexei discovered. Thanks!

> > +               /* nothing to do, output to stdout by default */
> > +               return;
> > +       }
> > +
> > +       /* stdout and stderr -> buffer */
> > +       fflush(stdout);
> > +
> > +       env.stdout = stdout;
> > +       env.stderr = stderr;
> > +
> > +       stdout = open_memstream(&env.log_buf, &env.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);
> > +       free(env.log_buf);
> > +
> > +       env.log_buf = NULL;
> > +       env.log_cnt = 0;
> > +
> > +       stdout = env.stdout;
> > +       stderr = env.stderr;
> > +#endif
> > +}
> > +
> >  int main(int argc, char **argv)
> >  {
> >         static const struct argp argp = {
> > @@ -496,6 +499,7 @@ int main(int argc, char **argv)
> >
> >         env.jit_enabled = is_jit_enabled();
> >
> > +       stdio_hijack();
> >         for (i = 0; i < prog_test_cnt; i++) {
> >                 struct prog_test_def *test = &prog_test_defs[i];
> >                 int old_pass_cnt = pass_cnt;
> > @@ -523,13 +527,14 @@ int main(int argc, char **argv)
> >
> >                 dump_test_log(test, test->error_cnt);
> >
> > -               printf("#%d %s:%s\n", test->test_num, test->test_name,
> > -                      test->error_cnt ? "FAIL" : "OK");
> > +               fprintf(env.stdout, "#%d %s:%s\n",
> > +                       test->test_num, test->test_name,
> > +                       test->error_cnt ? "FAIL" : "OK");
> >         }
> > +       stdio_restore();
> >         printf("Summary: %d/%d PASSED, %d FAILED\n",
> >                env.succ_cnt, env.sub_succ_cnt, env.fail_cnt);
> >
> > -       free(env.log_buf);
> >         free(env.test_selector.num_set);
> >         free(env.subtest_selector.num_set);
> >
> > diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> > index afd14962456f..541f9eab5eed 100644
> > --- a/tools/testing/selftests/bpf/test_progs.h
> > +++ b/tools/testing/selftests/bpf/test_progs.h
> > @@ -56,9 +56,10 @@ struct test_env {
> >         bool jit_enabled;
> >
> >         struct prog_test_def *test;
> > +       FILE *stdout;
> > +       FILE *stderr;
> >         char *log_buf;
> >         size_t log_cnt;
> > -       size_t log_cap;
> >
> >         int succ_cnt; /* successful tests */
> >         int sub_succ_cnt; /* successful sub-tests */
> > --
> > 2.22.0.770.g0f2c4a37fd-goog
> >