[PATH bpf-next 1/2] flow_dissector: Allow updating the flow dissector program atomically

It is currently not possible to detach the flow dissector program and
attach a new one in an atomic fashion, that is with a single syscall.
Attempts to do so will be met with EEXIST error.

This makes updates to flow dissector program hard. Traffic steering that
relies on BPF-powered flow dissection gets disrupted while old program has
been already detached but the new one has not been attached yet.

There is also a window of opportunity to attach a flow dissector to a
non-root namespace while updating the root flow dissector, thus blocking
the update.

Lastly, the behavior is inconsistent with cgroup BPF programs, which can be
replaced with a single bpf(BPF_PROG_ATTACH, ...) syscall without any
restrictions.

Allow attaching a new flow dissector program when another one is already
present with a restriction that it can't be the same program.

Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
---
 net/core/flow_dissector.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/net/core/flow_dissector.c b/net/core/flow_dissector.c
index 6b4b88d1599d..dbf502c18656 100644
--- a/net/core/flow_dissector.c
+++ b/net/core/flow_dissector.c

@@ -128,6 +128,8 @@ int skb_flow_dissector_bpf_prog_attach(const union bpf_attr *attr,
 		struct net *ns;
 
 		for_each_net(ns) {
+			if (ns == &init_net)
+				continue;
 			if (rcu_access_pointer(ns->flow_dissector_prog)) {
 				ret = -EEXIST;
 				goto out;

@@ -145,12 +147,14 @@ int skb_flow_dissector_bpf_prog_attach(const union bpf_attr *attr,
 
 	attached = rcu_dereference_protected(net->flow_dissector_prog,
 					     lockdep_is_held(&flow_dissector_mutex));
-	if (attached) {
-		/* Only one BPF program can be attached at a time */
-		ret = -EEXIST;
+	if (attached == prog) {
+		/* The same program cannot be attached twice */
+		ret = -EINVAL;
 		goto out;
 	}
 	rcu_assign_pointer(net->flow_dissector_prog, prog);
+	if (attached)
+		bpf_prog_put(attached);
 out:
 	mutex_unlock(&flow_dissector_mutex);
 	return ret;

-- 
2.20.1

Make sure a new flow dissector program can be attached to replace the old
one with a single syscall. Also check that attaching the same program twice
is prohibited.

Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
---
 .../bpf/prog_tests/flow_dissector_reattach.c  | 93 +++++++++++++++++++
 1 file changed, 93 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

diff --git a/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c
new file mode 100644
index 000000000000..0f0006c93956
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

@@ -0,0 +1,93 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Test that the flow_dissector program can be updated with a single
+ * syscall by attaching a new program that replaces the existing one.
+ *
+ * Corner case - the same program cannot be attached twice.
+ */
+#include <errno.h>
+#include <fcntl.h>
+#include <stdbool.h>
+#include <unistd.h>
+
+#include <linux/bpf.h>
+#include <bpf/bpf.h>
+
+#include "test_progs.h"
+
+/* Not used here. For CHECK macro sake only. */
+static int duration;
+
+static bool is_attached(void)
+{
+	bool attached = true;
+	int err, net_fd = -1;
+	__u32 cnt;
+
+	net_fd = open("/proc/self/ns/net", O_RDONLY);
+	if (net_fd < 0)
+		goto out;
+
+	err = bpf_prog_query(net_fd, BPF_FLOW_DISSECTOR, 0, NULL, NULL, &cnt);
+	if (CHECK(err, "bpf_prog_query", "ret %d errno %d\n", err, errno))
+		goto out;
+
+	attached = (cnt > 0);
+out:
+	close(net_fd);
+	return attached;
+}
+
+static int load_prog(void)
+{
+	struct bpf_insn prog[] = {
+		BPF_MOV64_IMM(BPF_REG_0, BPF_OK),
+		BPF_EXIT_INSN(),
+	};
+	int fd;
+
+	fd = bpf_load_program(BPF_PROG_TYPE_FLOW_DISSECTOR, prog,
+			      ARRAY_SIZE(prog), "GPL", 0, NULL, 0);
+	CHECK(fd < 0, "bpf_load_program", "ret %d errno %d\n", fd, errno);
+
+	return fd;
+}
+
+void test_flow_dissector_reattach(void)
+{
+	int prog_fd[2] = { -1, -1 };
+	int err;
+
+	if (is_attached())
+		return;
+
+	prog_fd[0] = load_prog();
+	if (prog_fd[0] < 0)
+		return;
+
+	prog_fd[1] = load_prog();
+	if (prog_fd[1] < 0)
+		goto out_close;
+
+	err = bpf_prog_attach(prog_fd[0], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-0", "ret %d errno %d\n", err, errno))
+		goto out_close;
+
+	/* Expect success when attaching a different program */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-1", "ret %d errno %d\n", err, errno))
+		goto out_detach;
+
+	/* Expect failure when attaching the same program twice */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	CHECK(!err || errno != EINVAL, "bpf_prog_attach-2",
+	      "ret %d errno %d\n", err, errno);
+
+out_detach:
+	err = bpf_prog_detach(0, BPF_FLOW_DISSECTOR);
+	CHECK(err, "bpf_prog_detach", "ret %d errno %d\n", err, errno);
+
+out_close:
+	close(prog_fd[1]);
+	close(prog_fd[0]);
+}

-- 
2.20.1

Subject should say 'PATCH bpf-next', naturally. Sorry for the typo.

-Jakub

On 10/09, Jakub Sitnicki wrote:

Make sure a new flow dissector program can be attached to replace the old
one with a single syscall. Also check that attaching the same program twice
is prohibited.

Overall the series looks good, left a bunch of nits/questions below.

[..]

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

+static bool is_attached(void)
+{
+	bool attached = true;
+	int err, net_fd = -1;

nit: maybe don't need to initialize net_fd to -1 here as well.

+	__u32 cnt;
+
+	net_fd = open("/proc/self/ns/net", O_RDONLY);
+	if (net_fd < 0)
+		goto out;
+
+	err = bpf_prog_query(net_fd, BPF_FLOW_DISSECTOR, 0, NULL, NULL, &cnt);
+	if (CHECK(err, "bpf_prog_query", "ret %d errno %d\n", err, errno))
+		goto out;
+
+	attached = (cnt > 0);
+out:
+	close(net_fd);
+	return attached;
+}
+
+static int load_prog(void)
+{
+	struct bpf_insn prog[] = {
+		BPF_MOV64_IMM(BPF_REG_0, BPF_OK),
+		BPF_EXIT_INSN(),
+	};
+	int fd;
+
+	fd = bpf_load_program(BPF_PROG_TYPE_FLOW_DISSECTOR, prog,
+			      ARRAY_SIZE(prog), "GPL", 0, NULL, 0);
+	CHECK(fd < 0, "bpf_load_program", "ret %d errno %d\n", fd, errno);
+
+	return fd;
+}
+
+void test_flow_dissector_reattach(void)
+{
+	int prog_fd[2] = { -1, -1 };
+	int err;
+
+	if (is_attached())
+		return;

Should we call test__skip() here to indicate that the test has been
skipped?
Also, do we need to run this test against non-root namespace as well?

+	prog_fd[0] = load_prog();
+	if (prog_fd[0] < 0)
+		return;
+
+	prog_fd[1] = load_prog();
+	if (prog_fd[1] < 0)
+		goto out_close;
+
+	err = bpf_prog_attach(prog_fd[0], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-0", "ret %d errno %d\n", err, errno))
+		goto out_close;
+
+	/* Expect success when attaching a different program */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-1", "ret %d errno %d\n", err, errno))
+		goto out_detach;
+
+	/* Expect failure when attaching the same program twice */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	CHECK(!err || errno != EINVAL, "bpf_prog_attach-2",
+	      "ret %d errno %d\n", err, errno);
+
+out_detach:
+	err = bpf_prog_detach(0, BPF_FLOW_DISSECTOR);
+	CHECK(err, "bpf_prog_detach", "ret %d errno %d\n", err, errno);
+
+out_close:
+	close(prog_fd[1]);
+	close(prog_fd[0]);
+}
-- 
2.20.1

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

On 10/09, Jakub Sitnicki wrote:

quoted

Make sure a new flow dissector program can be attached to replace the old
one with a single syscall. Also check that attaching the same program twice
is prohibited.

Overall the series looks good, left a bunch of nits/questions below.

Thanks for the comments.

quoted

Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
---
 .../bpf/prog_tests/flow_dissector_reattach.c  | 93 +++++++++++++++++++
 1 file changed, 93 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

diff --git a/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c
new file mode 100644
index 000000000000..0f0006c93956
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

@@ -0,0 +1,93 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Test that the flow_dissector program can be updated with a single
+ * syscall by attaching a new program that replaces the existing one.
+ *
+ * Corner case - the same program cannot be attached twice.
+ */
+#include <errno.h>
+#include <fcntl.h>
+#include <stdbool.h>
+#include <unistd.h>
+
+#include <linux/bpf.h>
+#include <bpf/bpf.h>
+
+#include "test_progs.h"
+

[..]

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;
}

It doesn't address the extra variable problem. Maybe we need another
CHECK variant.

quoted

+static bool is_attached(void)
+{
+	bool attached = true;
+	int err, net_fd = -1;

nit: maybe don't need to initialize net_fd to -1 here as well.

Will fix.

quoted

+	__u32 cnt;
+
+	net_fd = open("/proc/self/ns/net", O_RDONLY);
+	if (net_fd < 0)
+		goto out;
+
+	err = bpf_prog_query(net_fd, BPF_FLOW_DISSECTOR, 0, NULL, NULL, &cnt);
+	if (CHECK(err, "bpf_prog_query", "ret %d errno %d\n", err, errno))
+		goto out;
+
+	attached = (cnt > 0);
+out:
+	close(net_fd);
+	return attached;
+}
+
+static int load_prog(void)
+{
+	struct bpf_insn prog[] = {
+		BPF_MOV64_IMM(BPF_REG_0, BPF_OK),
+		BPF_EXIT_INSN(),
+	};
+	int fd;
+
+	fd = bpf_load_program(BPF_PROG_TYPE_FLOW_DISSECTOR, prog,
+			      ARRAY_SIZE(prog), "GPL", 0, NULL, 0);
+	CHECK(fd < 0, "bpf_load_program", "ret %d errno %d\n", fd, errno);
+
+	return fd;
+}
+
+void test_flow_dissector_reattach(void)
+{
+	int prog_fd[2] = { -1, -1 };
+	int err;
+
+	if (is_attached())
+		return;

Should we call test__skip() here to indicate that the test has been
skipped?
Also, do we need to run this test against non-root namespace as well?

Makes sense. Skip the test if anything is attached to root
namespace. Otherwise test twice, once in non-root and once in root
namespace.

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

Not sure what's a good fix.

Ideally - dup2(STDOUT_FILENO, ...). But memstream doesn't have an FD.
We can switch to fprintf(stdout, ...) which works for some reason.

-Jakub

quoted

+	prog_fd[0] = load_prog();
+	if (prog_fd[0] < 0)
+		return;
+
+	prog_fd[1] = load_prog();
+	if (prog_fd[1] < 0)
+		goto out_close;
+
+	err = bpf_prog_attach(prog_fd[0], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-0", "ret %d errno %d\n", err, errno))
+		goto out_close;
+
+	/* Expect success when attaching a different program */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-1", "ret %d errno %d\n", err, errno))
+		goto out_detach;
+
+	/* Expect failure when attaching the same program twice */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	CHECK(!err || errno != EINVAL, "bpf_prog_attach-2",
+	      "ret %d errno %d\n", err, errno);
+
+out_detach:
+	err = bpf_prog_detach(0, BPF_FLOW_DISSECTOR);
+	CHECK(err, "bpf_prog_detach", "ret %d errno %d\n", err, errno);
+
+out_close:
+	close(prog_fd[1]);
+	close(prog_fd[0]);
+}
--
2.20.1

On 10/10, Jakub Sitnicki wrote:

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

quoted

On 10/09, Jakub Sitnicki wrote:

quoted

Make sure a new flow dissector program can be attached to replace the old
one with a single syscall. Also check that attaching the same program twice
is prohibited.

Overall the series looks good, left a bunch of nits/questions below.

Thanks for the comments.

quoted

quoted

Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
---
 .../bpf/prog_tests/flow_dissector_reattach.c  | 93 +++++++++++++++++++
 1 file changed, 93 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

diff --git a/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c
new file mode 100644
index 000000000000..0f0006c93956
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/flow_dissector_reattach.c

@@ -0,0 +1,93 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Test that the flow_dissector program can be updated with a single
+ * syscall by attaching a new program that replaces the existing one.
+ *
+ * Corner case - the same program cannot be attached twice.
+ */
+#include <errno.h>
+#include <fcntl.h>
+#include <stdbool.h>
+#include <unistd.h>
+
+#include <linux/bpf.h>
+#include <bpf/bpf.h>
+
+#include "test_progs.h"
+

[..]

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>.

It doesn't address the extra variable problem. Maybe we need another
CHECK variant.

quoted

quoted

+static bool is_attached(void)
+{
+	bool attached = true;
+	int err, net_fd = -1;

nit: maybe don't need to initialize net_fd to -1 here as well.

Will fix.

quoted

quoted

+	__u32 cnt;
+
+	net_fd = open("/proc/self/ns/net", O_RDONLY);
+	if (net_fd < 0)
+		goto out;
+
+	err = bpf_prog_query(net_fd, BPF_FLOW_DISSECTOR, 0, NULL, NULL, &cnt);
+	if (CHECK(err, "bpf_prog_query", "ret %d errno %d\n", err, errno))
+		goto out;
+
+	attached = (cnt > 0);
+out:
+	close(net_fd);
+	return attached;
+}
+
+static int load_prog(void)
+{
+	struct bpf_insn prog[] = {
+		BPF_MOV64_IMM(BPF_REG_0, BPF_OK),
+		BPF_EXIT_INSN(),
+	};
+	int fd;
+
+	fd = bpf_load_program(BPF_PROG_TYPE_FLOW_DISSECTOR, prog,
+			      ARRAY_SIZE(prog), "GPL", 0, NULL, 0);
+	CHECK(fd < 0, "bpf_load_program", "ret %d errno %d\n", fd, errno);
+
+	return fd;
+}
+
+void test_flow_dissector_reattach(void)
+{
+	int prog_fd[2] = { -1, -1 };
+	int err;
+
+	if (is_attached())
+		return;

Should we call test__skip() here to indicate that the test has been
skipped?
Also, do we need to run this test against non-root namespace as well?

Makes sense. Skip the test if anything is attached to root
namespace. Otherwise test twice, once in non-root and once in root
namespace.

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

$

$ ldd --version
ldd (Debian GLIBC 2.28-10) 2.28

Not sure what's a good fix.

Ideally - dup2(STDOUT_FILENO, ...). But memstream doesn't have an FD.
We can switch to fprintf(stdout, ...) which works for some reason.

-Jakub

quoted

quoted

+	prog_fd[0] = load_prog();
+	if (prog_fd[0] < 0)
+		return;
+
+	prog_fd[1] = load_prog();
+	if (prog_fd[1] < 0)
+		goto out_close;
+
+	err = bpf_prog_attach(prog_fd[0], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-0", "ret %d errno %d\n", err, errno))
+		goto out_close;
+
+	/* Expect success when attaching a different program */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	if (CHECK(err, "bpf_prog_attach-1", "ret %d errno %d\n", err, errno))
+		goto out_detach;
+
+	/* Expect failure when attaching the same program twice */
+	err = bpf_prog_attach(prog_fd[1], 0, BPF_FLOW_DISSECTOR, 0);
+	CHECK(!err || errno != EINVAL, "bpf_prog_attach-2",
+	      "ret %d errno %d\n", err, errno);
+
+out_detach:
+	err = bpf_prog_detach(0, BPF_FLOW_DISSECTOR);
+	CHECK(err, "bpf_prog_detach", "ret %d errno %d\n", err, errno);
+
+out_close:
+	close(prog_fd[1]);
+	close(prog_fd[0]);
+}
--
2.20.1

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

On 10/10, Jakub Sitnicki wrote:

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

quoted

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

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.

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.

[...]

quoted

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.

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

quoted

$