Message-ID: <20191010170117.GG2096@mini-arch>
Date:   Thu, 10 Oct 2019 10:01:17 -0700
From:   Stanislav Fomichev <sdf@...ichev.me>
To:     Jakub Sitnicki <jakub@...udflare.com>
Cc:     bpf@...r.kernel.org, netdev@...r.kernel.org,
        kernel-team@...udflare.com, Stanislav Fomichev <sdf@...gle.com>
Subject: Re: [PATH bpf-next 2/2] selftests/bpf: Check that flow dissector can
 be re-attached

On 10/10, Jakub Sitnicki wrote:
> On Thu, Oct 10, 2019 at 06:31 PM CEST, Stanislav Fomichev wrote:
> > On 10/10, Jakub Sitnicki wrote:
> >> On Wed, Oct 09, 2019 at 06:33 PM CEST, Stanislav Fomichev wrote:
> >> > On 10/09, Jakub Sitnicki wrote:
> 
> [...]
> 
> >> >> +/* Not used here. For CHECK macro sake only. */
> >> >> +static int duration;
> >> > nit: you can use CHECK_FAIL macro instead which doesn't require this.
> >> >
> >> > if (CHECK_FAIL(expr)) {
> >> > 	printf("something bad has happened\n");
> >> > 	return/goto;
> >> > }
> >> >
> >> > It may be more verbose than doing CHECK() with its embedded error
> >> > message, so I leave it up to you to decide on whether you want to switch
> >> > to CHECK_FAIL or stick to CHECK.
> >> >
> >>
> >> I wouldn't mind switching to CHECK_FAIL. It reads better than CHECK with
> >> error message stuck in the if expression. (There is a side-issue with
> >> printf(). Will explain at the end [*].)
> >>
> >> Another thing to consider is that with CHECK the message indicating a
> >> failure ("<test>:FAIL:<lineno>") and the actual explanation message are
> >> on the same line. This makes the error log easier to reason.
> >>
> >> I'm torn here, and considering another alternative to address at least
> >> the readability issue:
> >>
> >> if (fail_expr) {
> >>         CHECK(1, "action", "explanation");
> >>         return;
> >> }
> > Can we use perror for the error reporting?
> >
> > if (CHECK(fail_expr)) {
> > 	perror("failed to do something"); // will print errno as well
> > }
> >
> > This should give all the info needed to grep for this message and debug
> > the problem.
> >
> > Alternatively, we can copy/move log_err() from the cgroup_helpers.h,
> > and use it in test_progs; it prints file:line:errno <msg>.
> 
> CHECK_FAIL + perror() works for me. I've been experimenting with
> extracting a new macro-helper (patch below) but perhaps it's an
> overkill.
If you want to go the route with the new helpers let's maybe have something
similar to what we have in the kernel? Stuff like pr_err (which is familiar)
so then the pattern can be:

if (CHECK(expr)) {
	pr_err("description"); // prints file:line:errno
	[return;]
}

But I'd stick with perror, grepping the message shouldn't be that hard
since we have a rule to not break the error strings.

> 
> [...]
> 
> >> [*] The printf() issue.
> >>
> >> I've noticed that stdio hijacking that test_progs runner applies doesn't
> >> quite work. printf() seems to skip the FILE stream buffer and write
> >> whole lines directly to stdout. This results in reordered messages on
> >> output.
> >>
> >> Here's a distilled reproducer for what test_progs does:
> >>
> >> int main(void)
> >> {
> >> 	FILE *stream;
> >> 	char *buf;
> >> 	size_t cnt;
> >>
> >> 	stream = stdout;
> >> 	stdout = open_memstream(&buf, &cnt);
> >> 	if (!stdout)
> >> 		error(1, errno, "open_memstream");
> >>
> >> 	printf("foo");
> >> 	printf("bar\n");
> >> 	printf("baz");
> >> 	printf("qux\n");
> >>
> >> 	fflush(stdout);
> >> 	fclose(stdout);
> >>
> >> 	buf[cnt] = '\0';
> >> 	fprintf(stream, "<<%s>>", buf);
> >> 	if (buf[cnt-1] != '\n')
> >> 		fprintf(stream, "\n");
> >>
> >> 	free(buf);
> >> 	return 0;
> >> }
> >>
> >> On output we get:
> >>
> >> $ ./hijack_stdout
> >> bar
> >> qux
> >> <<foobaz>>
> >> $
> > What glibc do you have? I don't see any issues with your reproducer
> > on my setup:
> >
> > $ ./a.out
> > <<foobar
> > bazqux
> >>>$
> >
> > $ ldd --version
> > ldd (Debian GLIBC 2.28-10) 2.28
> >
> 
> Interesting. I'm on the same version, different distro:
> 
> $ rpm -q glibc
> glibc-2.28-33.fc29.x86_64
> glibc-2.28-33.fc29.i686
> 
> I'll need to dig deeper. Thanks for keeping me honest here.
I also tried it on my other box with 2.29 and now I see the issue you're
reporting:

$ gcc tmp.c && ./a.out 
bar
qux
<<foobaz>>

But what's interesting:

$ gcc -static tmp.c && ./a.out 
<<foobar
bazqux
>>$ 

> -Jakub
> 
> ---8<---
> 
> From 66fd85cd3bbb36cf99c8b6cbbb161d3c0533263b Mon Sep 17 00:00:00 2001
> From: Jakub Sitnicki <jakub@...udflare.com>
> Date: Thu, 10 Oct 2019 15:29:28 +0200
> Subject: [PATCH net-next] selftests/bpf: test_progs: Extract a macro for
>  logging failures
> 
> When selecting a macro-helper to use for logging a test failure we are
> faced with a choice between the shortcomings of CHECK and CHECK_FAIL.
> 
> CHECK is intended to be used in conjunction with bpf_prog_test_run(). It
> expects a program run duration to be passed to it as an implicit argument.
> 
> While CHECK_FAIL is more generic but compared to CHECK doesn't allow
> logging a custom error message to explain the failure.
> 
> Introduce a new macro-helper - FAIL, that is lower-level than the above it
> and it intended to be used just log the failure with an explanation for it.
> 
> Because FAIL does in part what CHECK and CHECK_FAIL do, we can reuse it in
> these macros. One side-effect is a slight the change in the log format. We
> always display the line number where a check has passed/failed.
> 
> Signed-off-by: Jakub Sitnicki <jakub@...udflare.com>
> ---
>  tools/testing/selftests/bpf/test_progs.h | 17 ++++++++++-------
>  1 file changed, 10 insertions(+), 7 deletions(-)
> 
> diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> index 0c48f64f732b..9e203ff71b78 100644
> --- a/tools/testing/selftests/bpf/test_progs.h
> +++ b/tools/testing/selftests/bpf/test_progs.h
> @@ -92,15 +92,19 @@ struct ipv6_packet {
>  } __packed;
>  extern struct ipv6_packet pkt_v6;
>  
> +#define FAIL(tag, format...) ({						\
> +	test__fail();							\
> +	printf("%s:%d:FAIL:%s ", __func__, __LINE__, tag);		\
> +	printf(format);							\
> +})
> +
>  #define _CHECK(condition, tag, duration, format...) ({			\
>  	int __ret = !!(condition);					\
>  	if (__ret) {							\
> -		test__fail();						\
> -		printf("%s:FAIL:%s ", __func__, tag);			\
> -		printf(format);						\
> +		FAIL(tag, format);					\
>  	} else {							\
> -		printf("%s:PASS:%s %d nsec\n",				\
> -		       __func__, tag, duration);			\
> +		printf("%s:%d:PASS:%s %d nsec\n",			\
> +		       __func__, __LINE__, tag, duration);		\
>  	}								\
>  	__ret;								\
>  })
> @@ -108,8 +112,7 @@ extern struct ipv6_packet pkt_v6;
>  #define CHECK_FAIL(condition) ({					\
>  	int __ret = !!(condition);					\
>  	if (__ret) {							\
> -		test__fail();						\
> -		printf("%s:FAIL:%d\n", __func__, __LINE__);		\
> +		FAIL("", #condition "\n");				\
>  	}								\
>  	__ret;								\
>  })
> -- 
> 2.20.1
> 

Powered by blists - more mailing lists