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

On Thu, Oct 10, 2019 at 06:31 PM CEST, Stanislav Fomichev wrote:

On 10/10, Jakub Sitnicki wrote:

quoted

On Wed, Oct 09, 2019 at 06:33 PM CEST, Stanislav Fomichev wrote:

quoted

On 10/09, Jakub Sitnicki wrote:

[...]

quoted

quoted

quoted

+/* 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.

[...]

quoted

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

quoted

quoted

$

$ 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