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