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 <ja...@cloudflare.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 <ja...@cloudflare.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
>
