Steven suggested a way to resolve the appearance of the warning banner
that appears as a result of using trace_printk() in BPF [1].
Applying the patch and testing reveals all works as expected; we
can call bpf_trace_printk() and see the trace messages in
/sys/kernel/debug/tracing/trace_pipe and no banner message appears.
Also add a test prog to verify basic bpf_trace_printk() helper behaviour.
Changes since v1:
- reorder header inclusion in bpf_trace.c (Steven, patch 1)
- trace zero-length messages also (Andrii, patch 1)
- use a raw spinlock to ensure there are no issues for PREMMPT_RT
kernels when using bpf_trace_printk() within other raw spinlocks
(Steven, patch 1)
- always enable bpf_trace_printk() tracepoint when loading programs
using bpf_trace_printk() as this will ensure that a user disabling
that tracepoint will not prevent tracing output from being logged
(Steven, patch 1)
- use "tp/raw_syscalls/sys_enter" and a usleep(1) to trigger events
in the selftest ensuring test runs faster (Andrii, patch 2)
[1] https://lore.kernel.org/r/[email protected]
Alan Maguire (2):
bpf: use dedicated bpf_trace_printk event instead of trace_printk()
selftests/bpf: add selftests verifying bpf_trace_printk() behaviour
kernel/trace/Makefile | 2 +
kernel/trace/bpf_trace.c | 41 ++++++++++--
kernel/trace/bpf_trace.h | 34 ++++++++++
.../selftests/bpf/prog_tests/trace_printk.c | 74 ++++++++++++++++++++++
tools/testing/selftests/bpf/progs/trace_printk.c | 21 ++++++
5 files changed, 167 insertions(+), 5 deletions(-)
create mode 100644 kernel/trace/bpf_trace.h
create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_printk.c
create mode 100644 tools/testing/selftests/bpf/progs/trace_printk.c
--
1.8.3.1
Simple selftests that verifies bpf_trace_printk() returns a sensible
value and tracing messages appear.
Signed-off-by: Alan Maguire <[email protected]>
---
.../selftests/bpf/prog_tests/trace_printk.c | 74 ++++++++++++++++++++++
tools/testing/selftests/bpf/progs/trace_printk.c | 21 ++++++
2 files changed, 95 insertions(+)
create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_printk.c
create mode 100644 tools/testing/selftests/bpf/progs/trace_printk.c
diff --git a/tools/testing/selftests/bpf/prog_tests/trace_printk.c b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
new file mode 100644
index 0000000..25dd0f47
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
@@ -0,0 +1,74 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2020, Oracle and/or its affiliates. */
+
+#include <test_progs.h>
+
+#include "trace_printk.skel.h"
+
+#define TRACEBUF "/sys/kernel/debug/tracing/trace_pipe"
+#define SEARCHMSG "testing,testing"
+
+void test_trace_printk(void)
+{
+ int err, iter = 0, duration = 0, found = 0, fd = -1;
+ struct trace_printk__bss *bss;
+ struct trace_printk *skel;
+ char buf[1024];
+
+ skel = trace_printk__open();
+ if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
+ return;
+
+ err = trace_printk__load(skel);
+ if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))
+ goto cleanup;
+
+ bss = skel->bss;
+
+ err = trace_printk__attach(skel);
+ if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
+ goto cleanup;
+
+ fd = open(TRACEBUF, O_RDONLY);
+ if (CHECK(fd < 0, "could not open trace buffer",
+ "error %d opening %s", errno, TRACEBUF))
+ goto cleanup;
+
+ /* We do not want to wait forever if this test fails... */
+ fcntl(fd, F_SETFL, O_NONBLOCK);
+
+ /* wait for tracepoint to trigger */
+ usleep(1);
+ trace_printk__detach(skel);
+
+ if (CHECK(bss->trace_printk_ran == 0,
+ "bpf_trace_printk never ran",
+ "ran == %d", bss->trace_printk_ran))
+ goto cleanup;
+
+ if (CHECK(bss->trace_printk_ret <= 0,
+ "bpf_trace_printk returned <= 0 value",
+ "got %d", bss->trace_printk_ret))
+ goto cleanup;
+
+ /* verify our search string is in the trace buffer */
+ while (read(fd, buf, sizeof(buf)) >= 0 || errno == EAGAIN) {
+ if (strstr(buf, SEARCHMSG) != NULL)
+ found++;
+ if (found == bss->trace_printk_ran)
+ break;
+ if (++iter > 1000)
+ break;
+ }
+
+ if (CHECK(!found, "message from bpf_trace_printk not found",
+ "no instance of %s in %s", SEARCHMSG, TRACEBUF))
+ goto cleanup;
+
+ printf("ran %d times; last return value %d, with %d instances of msg\n",
+ bss->trace_printk_ran, bss->trace_printk_ret, found);
+cleanup:
+ trace_printk__destroy(skel);
+ if (fd != -1)
+ close(fd);
+}
diff --git a/tools/testing/selftests/bpf/progs/trace_printk.c b/tools/testing/selftests/bpf/progs/trace_printk.c
new file mode 100644
index 0000000..8ca7f39
--- /dev/null
+++ b/tools/testing/selftests/bpf/progs/trace_printk.c
@@ -0,0 +1,21 @@
+// SPDX-License-Identifier: GPL-2.0
+// Copyright (c) 2020, Oracle and/or its affiliates.
+
+#include "vmlinux.h"
+#include <bpf/bpf_helpers.h>
+#include <bpf/bpf_tracing.h>
+
+char _license[] SEC("license") = "GPL";
+
+int trace_printk_ret = 0;
+int trace_printk_ran = 0;
+
+SEC("tp/raw_syscalls/sys_enter")
+int sys_enter(void *ctx)
+{
+ static const char fmt[] = "testing,testing %d\n";
+
+ trace_printk_ret = bpf_trace_printk(fmt, sizeof(fmt),
+ ++trace_printk_ran);
+ return 0;
+}
--
1.8.3.1
On Fri, Jul 10, 2020 at 7:25 AM Alan Maguire <[email protected]> wrote:
>
> Simple selftests that verifies bpf_trace_printk() returns a sensible
> value and tracing messages appear.
>
> Signed-off-by: Alan Maguire <[email protected]>
> ---
see pedantic note below, but I don't think that's an issue in practice
Acked-by: Andrii Nakryiko <[email protected]>
> .../selftests/bpf/prog_tests/trace_printk.c | 74 ++++++++++++++++++++++
> tools/testing/selftests/bpf/progs/trace_printk.c | 21 ++++++
> 2 files changed, 95 insertions(+)
> create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_printk.c
> create mode 100644 tools/testing/selftests/bpf/progs/trace_printk.c
>
[...]
> +
> + /* verify our search string is in the trace buffer */
> + while (read(fd, buf, sizeof(buf)) >= 0 || errno == EAGAIN) {
There is a minor chance that "testing,testing" won't be found, if it
so happened that the first part is in the first read buffer, and the
second is in the second. I don't think it's ever the case for our CI
and for my local testing setup, but could be a cause of some
instability if there is something else emitting data to trace_pipe,
right?
Maybe line-based reading would be more reliable (unless printk can
intermix, not sure about that, in which case there is simply no way to
solve this 100% reliably).
> + if (strstr(buf, SEARCHMSG) != NULL)
> + found++;
> + if (found == bss->trace_printk_ran)
> + break;
> + if (++iter > 1000)
> + break;
> + }
> +
> + if (CHECK(!found, "message from bpf_trace_printk not found",
> + "no instance of %s in %s", SEARCHMSG, TRACEBUF))
> + goto cleanup;
> +
> + printf("ran %d times; last return value %d, with %d instances of msg\n",
> + bss->trace_printk_ran, bss->trace_printk_ret, found);
Is this needed or it's some debug leftover?
> +cleanup:
> + trace_printk__destroy(skel);
> + if (fd != -1)
> + close(fd);
> +}
[...]