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

[Stanislav Fomichev <sdf@fomichev.me>]

On 08/02, Andrii Nakryiko wrote:
> On 8/2/19 10:17 AM, Stanislav Fomichev 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.
> 
> I really like the idea. I didn't know about open_memstream, it's awesome. Thanks!
One possible downside of using open_memstream is that it's glibc
specific. I probably need to wrap it in #ifdef __GLIBC__ to make
it work with other libcs and just print everything as it was before :-(.
I'm not sure we care though.

> > test_{v,}printf are now simple wrappers around stdout and will be
> > removed in the next patch.
> >
> > Cc: Andrii Nakryiko <andriin@fb.com>
> > Signed-off-by: Stanislav Fomichev <sdf@google.com>
> > ---
> >  tools/testing/selftests/bpf/test_progs.c | 100 ++++++++++-------------
> >  tools/testing/selftests/bpf/test_progs.h |   2 +-
> >  2 files changed, 46 insertions(+), 56 deletions(-)
> >
> > diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
> > index db00196c8315..00d1565d01a3 100644
> > --- a/tools/testing/selftests/bpf/test_progs.c
> > +++ b/tools/testing/selftests/bpf/test_progs.c
> > @@ -40,14 +40,22 @@ 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 (env.verbose || test->force_log || failed) {
> > -		if (env.log_cnt) {
> > -			fprintf(stdout, "%s", env.log_buf);
> > -			if (env.log_buf[env.log_cnt - 1] != '\n')
> > -				fprintf(stdout, "\n");
> > +	if (stdout == env.stdout)
> > +		return;
> > +
> > +	fflush(stdout); /* exports env.log_buf & env.log_cap */
> > +
> > +	if (env.log_cap && (env.verbose || test->force_log || failed)) {
> > +		int len = strlen(env.log_buf);
> 
> env.log_cap is not really a capacity, it's actual number of bytes (without terminating zero), so there is no need to do strlen and it's probably better to rename env.log_cap into env.log_cnt.
I'll rename it to log_size to match open_memstream args.
We probably still need to do strlen because open_memstream can allocate
bigger buffer to hold the data.

> > +
> > +		if (len) {
> > +			fprintf(env.stdout, "%s", env.log_buf);
> > +			if (env.log_buf[len - 1] != '\n')
> > +				fprintf(env.stdout, "\n");
> > +
> > +			fseeko(stdout, 0, SEEK_SET);
> Same bug as I already fixed with env.log_cnt = 0 being inside this if. You want to do seek always, not just when you print output log.
SG, will move to where we currently clear log_cnt, thanks!

> >  /* rewind */
> >  		}
> >  	}
> > -	env.log_cnt = 0;
> >  }
> >  
> >  void test__end_subtest()
> > @@ -62,7 +70,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");
> >  }
> > @@ -100,53 +108,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 +439,32 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state)
> >  	return 0;
> >  }
> >  
> > +static void stdout_hijack(void)
> > +{
> > +	if (env.verbose || (env.test && env.test->force_log)) {
> > +		/* nothing to do, output to stdout by default */
> > +		return;
> > +	}
> > +
> > +	/* stdout -> buffer */
> > +	fflush(stdout);
> > +	stdout = open_memstream(&env.log_buf, &env.log_cap);
> Check errors and restore original stdout if something went wrong? (And emit some warning to stderr).
Good point, will do.

> > +}
> > +
> > +static void stdout_restore(void)
> > +{
> > +	if (stdout == env.stdout)
> > +		return;
> > +
> > +	fclose(stdout);
> > +	free(env.log_buf);
> > +
> > +	env.log_buf = NULL;
> > +	env.log_cap = 0;
> > +
> > +	stdout = env.stdout;
> > +}
> > +
> >  int main(int argc, char **argv)
> >  {
> >  	static const struct argp argp = {
> > @@ -495,6 +483,7 @@ int main(int argc, char **argv)
> >  	srand(time(NULL));
> >  
> >  	env.jit_enabled = is_jit_enabled();
> > +	env.stdout = stdout;
> >  
> >  	for (i = 0; i < prog_test_cnt; i++) {
> >  		struct prog_test_def *test = &prog_test_defs[i];
> > @@ -508,6 +497,7 @@ int main(int argc, char **argv)
> >  				test->test_num, test->test_name))
> >  			continue;
> >  
> > +		stdout_hijack();
> Why do you do this for every test? Just do once before all the tests and restore after?
We can do that, my thinking was to limit the area of hijacking :-)
But that would work as well, less allocations per test, I guess. Will
do.

> >  		test->run_test();
> >  		/* ensure last sub-test is finalized properly */
> >  		if (test->subtest_name)
> > @@ -522,6 +512,7 @@ int main(int argc, char **argv)
> >  			env.succ_cnt++;
> >  
> >  		dump_test_log(test, test->error_cnt);
> > +		stdout_restore();
> >  
> >  		printf("#%d %s:%s\n", test->test_num, test->test_name,
> >  		       test->error_cnt ? "FAIL" : "OK");
> > @@ -529,7 +520,6 @@ int main(int argc, char **argv)
> >  	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..9fd89078494f 100644
> > --- a/tools/testing/selftests/bpf/test_progs.h
> > +++ b/tools/testing/selftests/bpf/test_progs.h
> > @@ -56,8 +56,8 @@ struct test_env {
> >  	bool jit_enabled;
> >  
> >  	struct prog_test_def *test;
> > +	FILE *stdout;
> >  	char *log_buf;
> > -	size_t log_cnt;
> >  	size_t log_cap;
> So it's actually log_cnt that's assigned on fflush for memstream, according to man page, so probably keep log_cnt, delete log_cap.
Ack. See above, will rename to log_size, let me know if you disagree.

> >  	int succ_cnt; /* successful tests */