Re: [PATH bpf-next 2/2] selftests/bpf: Check that flow dissector can be re-attached

[Jakub Sitnicki <jakub@cloudflare.com>]

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.

[...]

>> [*] 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.

-Jakub

---8<---

From 66fd85cd3bbb36cf99c8b6cbbb161d3c0533263b Mon Sep 17 00:00:00 2001
From: Jakub Sitnicki <jakub@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 <jakub@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