lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Date:   Tue, 6 Aug 2019 10:29:00 -0700
From:   Andrii Nakryiko <andrii.nakryiko@...il.com>
To:     Stanislav Fomichev <sdf@...gle.com>
Cc:     Networking <netdev@...r.kernel.org>, bpf <bpf@...r.kernel.org>,
        "David S. Miller" <davem@...emloft.net>,
        Alexei Starovoitov <ast@...nel.org>,
        Daniel Borkmann <daniel@...earbox.net>,
        Andrii Nakryiko <andriin@...com>
Subject: Re: [PATCH bpf-next v4 1/3] selftests/bpf: test_progs: switch to open_memstream

On Tue, Aug 6, 2019 at 10:19 AM Stanislav Fomichev <sdf@...gle.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@...com>
> Acked-by: Andrii Nakryiko <andriin@...com>
> Signed-off-by: Stanislav Fomichev <sdf@...gle.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.

> +               /* 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
>

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ