* [PATCH v2 bpf-next 0/2] bpf: fix use of trace_printk() in BPF @ 2020-07-10 14:22 Alan Maguire 2020-07-10 14:22 ` [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() Alan Maguire 2020-07-10 14:22 ` [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour Alan Maguire 0 siblings, 2 replies; 6+ messages in thread From: Alan Maguire @ 2020-07-10 14:22 UTC (permalink / raw) To: rostedt, mingo, ast, daniel, andriin Cc: kafai, songliubraving, yhs, john.fastabend, kpsingh, linux-kernel, netdev, bpf, Alan Maguire 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/20200628194334.6238b933@oasis.local.home 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 ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() 2020-07-10 14:22 [PATCH v2 bpf-next 0/2] bpf: fix use of trace_printk() in BPF Alan Maguire @ 2020-07-10 14:22 ` Alan Maguire 2020-07-10 20:55 ` Andrii Nakryiko 2020-07-10 23:04 ` Daniel Borkmann 2020-07-10 14:22 ` [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour Alan Maguire 1 sibling, 2 replies; 6+ messages in thread From: Alan Maguire @ 2020-07-10 14:22 UTC (permalink / raw) To: rostedt, mingo, ast, daniel, andriin Cc: kafai, songliubraving, yhs, john.fastabend, kpsingh, linux-kernel, netdev, bpf, Alan Maguire The bpf helper bpf_trace_printk() uses trace_printk() under the hood. This leads to an alarming warning message originating from trace buffer allocation which occurs the first time a program using bpf_trace_printk() is loaded. We can instead create a trace event for bpf_trace_printk() and enable it in-kernel when/if we encounter a program using the bpf_trace_printk() helper. With this approach, trace_printk() is not used directly and no warning message appears. This work was started by Steven (see Link) and finished by Alan; added Steven's Signed-off-by with his permission. Link: https://lore.kernel.org/r/20200628194334.6238b933@oasis.local.home Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org> Signed-off-by: Alan Maguire <alan.maguire@oracle.com> --- kernel/trace/Makefile | 2 ++ kernel/trace/bpf_trace.c | 41 ++++++++++++++++++++++++++++++++++++----- kernel/trace/bpf_trace.h | 34 ++++++++++++++++++++++++++++++++++ 3 files changed, 72 insertions(+), 5 deletions(-) create mode 100644 kernel/trace/bpf_trace.h diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile index 6575bb0..aeba5ee 100644 --- a/kernel/trace/Makefile +++ b/kernel/trace/Makefile @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE GCOV_PROFILE := y endif +CFLAGS_bpf_trace.o := -I$(src) + CFLAGS_trace_benchmark.o := -I$(src) CFLAGS_trace_events_filter.o := -I$(src) diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c index 1d874d8..1414bf5 100644 --- a/kernel/trace/bpf_trace.c +++ b/kernel/trace/bpf_trace.c @@ -11,6 +11,7 @@ #include <linux/uaccess.h> #include <linux/ctype.h> #include <linux/kprobes.h> +#include <linux/spinlock.h> #include <linux/syscalls.h> #include <linux/error-injection.h> @@ -19,6 +20,9 @@ #include "trace_probe.h" #include "trace.h" +#define CREATE_TRACE_POINTS +#include "bpf_trace.h" + #define bpf_event_rcu_dereference(p) \ rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex)) @@ -374,6 +378,29 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, } } +static DEFINE_RAW_SPINLOCK(trace_printk_lock); + +#define BPF_TRACE_PRINTK_SIZE 1024 + + +static inline __printf(1, 0) int bpf_do_trace_printk(const char *fmt, ...) +{ + static char buf[BPF_TRACE_PRINTK_SIZE]; + unsigned long flags; + va_list ap; + int ret; + + raw_spin_lock_irqsave(&trace_printk_lock, flags); + va_start(ap, fmt); + ret = vsnprintf(buf, BPF_TRACE_PRINTK_SIZE, fmt, ap); + va_end(ap); + if (ret >= 0) + trace_bpf_trace_printk(buf); + raw_spin_unlock_irqrestore(&trace_printk_lock, flags); + + return ret; +} + /* * Only limited trace_printk() conversion specifiers allowed: * %d %i %u %x %ld %li %lu %lx %lld %lli %llu %llx %p %pB %pks %pus %s @@ -483,8 +510,7 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, */ #define __BPF_TP_EMIT() __BPF_ARG3_TP() #define __BPF_TP(...) \ - __trace_printk(0 /* Fake ip */, \ - fmt, ##__VA_ARGS__) + bpf_do_trace_printk(fmt, ##__VA_ARGS__) #define __BPF_ARG1_TP(...) \ ((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64)) \ @@ -521,10 +547,15 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, const struct bpf_func_proto *bpf_get_trace_printk_proto(void) { /* - * this program might be calling bpf_trace_printk, - * so allocate per-cpu printk buffers + * This program might be calling bpf_trace_printk, + * so enable the associated bpf_trace/bpf_trace_printk event. + * Repeat this each time as it is possible a user has + * disabled bpf_trace_printk events. By loading a program + * calling bpf_trace_printk() however the user has expressed + * the intent to see such events. */ - trace_printk_init_buffers(); + if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1)) + pr_warn_ratelimited("could not enable bpf_trace_printk events"); return &bpf_trace_printk_proto; } diff --git a/kernel/trace/bpf_trace.h b/kernel/trace/bpf_trace.h new file mode 100644 index 0000000..9acbc11 --- /dev/null +++ b/kernel/trace/bpf_trace.h @@ -0,0 +1,34 @@ +/* SPDX-License-Identifier: GPL-2.0 */ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM bpf_trace + +#if !defined(_TRACE_BPF_TRACE_H) || defined(TRACE_HEADER_MULTI_READ) + +#define _TRACE_BPF_TRACE_H + +#include <linux/tracepoint.h> + +TRACE_EVENT(bpf_trace_printk, + + TP_PROTO(const char *bpf_string), + + TP_ARGS(bpf_string), + + TP_STRUCT__entry( + __string(bpf_string, bpf_string) + ), + + TP_fast_assign( + __assign_str(bpf_string, bpf_string); + ), + + TP_printk("%s", __get_str(bpf_string)) +); + +#endif /* _TRACE_BPF_TRACE_H */ + +#undef TRACE_INCLUDE_PATH +#define TRACE_INCLUDE_PATH . +#define TRACE_INCLUDE_FILE bpf_trace + +#include <trace/define_trace.h> -- 1.8.3.1 ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() 2020-07-10 14:22 ` [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() Alan Maguire @ 2020-07-10 20:55 ` Andrii Nakryiko 2020-07-10 23:04 ` Daniel Borkmann 1 sibling, 0 replies; 6+ messages in thread From: Andrii Nakryiko @ 2020-07-10 20:55 UTC (permalink / raw) To: Alan Maguire Cc: Steven Rostedt, Ingo Molnar, Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, Martin Lau, Song Liu, Yonghong Song, john fastabend, KP Singh, open list, Networking, bpf On Fri, Jul 10, 2020 at 7:25 AM Alan Maguire <alan.maguire@oracle.com> wrote: > > The bpf helper bpf_trace_printk() uses trace_printk() under the hood. > This leads to an alarming warning message originating from trace > buffer allocation which occurs the first time a program using > bpf_trace_printk() is loaded. > > We can instead create a trace event for bpf_trace_printk() and enable > it in-kernel when/if we encounter a program using the > bpf_trace_printk() helper. With this approach, trace_printk() > is not used directly and no warning message appears. > > This work was started by Steven (see Link) and finished by Alan; added > Steven's Signed-off-by with his permission. > > Link: https://lore.kernel.org/r/20200628194334.6238b933@oasis.local.home > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org> > Signed-off-by: Alan Maguire <alan.maguire@oracle.com> > --- LGTM. Acked-by: Andrii Nakryiko <andriin@fb.com> > kernel/trace/Makefile | 2 ++ > kernel/trace/bpf_trace.c | 41 ++++++++++++++++++++++++++++++++++++----- > kernel/trace/bpf_trace.h | 34 ++++++++++++++++++++++++++++++++++ > 3 files changed, 72 insertions(+), 5 deletions(-) > create mode 100644 kernel/trace/bpf_trace.h > [...] ^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() 2020-07-10 14:22 ` [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() Alan Maguire 2020-07-10 20:55 ` Andrii Nakryiko @ 2020-07-10 23:04 ` Daniel Borkmann 1 sibling, 0 replies; 6+ messages in thread From: Daniel Borkmann @ 2020-07-10 23:04 UTC (permalink / raw) To: Alan Maguire, rostedt, mingo, ast, andriin Cc: kafai, songliubraving, yhs, john.fastabend, kpsingh, linux-kernel, netdev, bpf On 7/10/20 4:22 PM, Alan Maguire wrote: > The bpf helper bpf_trace_printk() uses trace_printk() under the hood. > This leads to an alarming warning message originating from trace > buffer allocation which occurs the first time a program using > bpf_trace_printk() is loaded. > > We can instead create a trace event for bpf_trace_printk() and enable > it in-kernel when/if we encounter a program using the > bpf_trace_printk() helper. With this approach, trace_printk() > is not used directly and no warning message appears. > > This work was started by Steven (see Link) and finished by Alan; added > Steven's Signed-off-by with his permission. > > Link: https://lore.kernel.org/r/20200628194334.6238b933@oasis.local.home > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org> > Signed-off-by: Alan Maguire <alan.maguire@oracle.com> > --- > kernel/trace/Makefile | 2 ++ > kernel/trace/bpf_trace.c | 41 ++++++++++++++++++++++++++++++++++++----- > kernel/trace/bpf_trace.h | 34 ++++++++++++++++++++++++++++++++++ > 3 files changed, 72 insertions(+), 5 deletions(-) > create mode 100644 kernel/trace/bpf_trace.h > > diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile > index 6575bb0..aeba5ee 100644 > --- a/kernel/trace/Makefile > +++ b/kernel/trace/Makefile > @@ -31,6 +31,8 @@ ifdef CONFIG_GCOV_PROFILE_FTRACE > GCOV_PROFILE := y > endif > > +CFLAGS_bpf_trace.o := -I$(src) > + > CFLAGS_trace_benchmark.o := -I$(src) > CFLAGS_trace_events_filter.o := -I$(src) > > diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c > index 1d874d8..1414bf5 100644 > --- a/kernel/trace/bpf_trace.c > +++ b/kernel/trace/bpf_trace.c > @@ -11,6 +11,7 @@ > #include <linux/uaccess.h> > #include <linux/ctype.h> > #include <linux/kprobes.h> > +#include <linux/spinlock.h> > #include <linux/syscalls.h> > #include <linux/error-injection.h> > > @@ -19,6 +20,9 @@ > #include "trace_probe.h" > #include "trace.h" > > +#define CREATE_TRACE_POINTS > +#include "bpf_trace.h" > + > #define bpf_event_rcu_dereference(p) \ > rcu_dereference_protected(p, lockdep_is_held(&bpf_event_mutex)) > > @@ -374,6 +378,29 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, > } > } > > +static DEFINE_RAW_SPINLOCK(trace_printk_lock); > + > +#define BPF_TRACE_PRINTK_SIZE 1024 > + > + nit: double newline > +static inline __printf(1, 0) int bpf_do_trace_printk(const char *fmt, ...) > +{ > + static char buf[BPF_TRACE_PRINTK_SIZE]; > + unsigned long flags; > + va_list ap; > + int ret; > + > + raw_spin_lock_irqsave(&trace_printk_lock, flags); > + va_start(ap, fmt); > + ret = vsnprintf(buf, BPF_TRACE_PRINTK_SIZE, fmt, ap); nit: s/BPF_TRACE_PRINTK_SIZE/sizeof(buf)/ > + va_end(ap); > + if (ret >= 0) > + trace_bpf_trace_printk(buf); Is there a specific reason you added the 'ret >= 0' check on top of [0]? Given the vsnprintf() internals you either return 0 or number of characters generated, no? [0] https://lore.kernel.org/bpf/20200628194334.6238b933@oasis.local.home/ Rest lgtm, thanks! > + raw_spin_unlock_irqrestore(&trace_printk_lock, flags); > + > + return ret; > +} > + > /* > * Only limited trace_printk() conversion specifiers allowed: > * %d %i %u %x %ld %li %lu %lx %lld %lli %llu %llx %p %pB %pks %pus %s > @@ -483,8 +510,7 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, > */ > #define __BPF_TP_EMIT() __BPF_ARG3_TP() > #define __BPF_TP(...) \ > - __trace_printk(0 /* Fake ip */, \ > - fmt, ##__VA_ARGS__) > + bpf_do_trace_printk(fmt, ##__VA_ARGS__) > > #define __BPF_ARG1_TP(...) \ > ((mod[0] == 2 || (mod[0] == 1 && __BITS_PER_LONG == 64)) \ > @@ -521,10 +547,15 @@ static void bpf_trace_copy_string(char *buf, void *unsafe_ptr, char fmt_ptype, > const struct bpf_func_proto *bpf_get_trace_printk_proto(void) > { > /* > - * this program might be calling bpf_trace_printk, > - * so allocate per-cpu printk buffers > + * This program might be calling bpf_trace_printk, > + * so enable the associated bpf_trace/bpf_trace_printk event. > + * Repeat this each time as it is possible a user has > + * disabled bpf_trace_printk events. By loading a program > + * calling bpf_trace_printk() however the user has expressed > + * the intent to see such events. > */ > - trace_printk_init_buffers(); > + if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1)) > + pr_warn_ratelimited("could not enable bpf_trace_printk events"); > > return &bpf_trace_printk_proto; > } > diff --git a/kernel/trace/bpf_trace.h b/kernel/trace/bpf_trace.h > new file mode 100644 > index 0000000..9acbc11 > --- /dev/null > +++ b/kernel/trace/bpf_trace.h > @@ -0,0 +1,34 @@ > +/* SPDX-License-Identifier: GPL-2.0 */ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM bpf_trace > + > +#if !defined(_TRACE_BPF_TRACE_H) || defined(TRACE_HEADER_MULTI_READ) > + > +#define _TRACE_BPF_TRACE_H > + > +#include <linux/tracepoint.h> > + > +TRACE_EVENT(bpf_trace_printk, > + > + TP_PROTO(const char *bpf_string), > + > + TP_ARGS(bpf_string), > + > + TP_STRUCT__entry( > + __string(bpf_string, bpf_string) > + ), > + > + TP_fast_assign( > + __assign_str(bpf_string, bpf_string); > + ), > + > + TP_printk("%s", __get_str(bpf_string)) > +); > + > +#endif /* _TRACE_BPF_TRACE_H */ > + > +#undef TRACE_INCLUDE_PATH > +#define TRACE_INCLUDE_PATH . > +#define TRACE_INCLUDE_FILE bpf_trace > + > +#include <trace/define_trace.h> > ^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour 2020-07-10 14:22 [PATCH v2 bpf-next 0/2] bpf: fix use of trace_printk() in BPF Alan Maguire 2020-07-10 14:22 ` [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() Alan Maguire @ 2020-07-10 14:22 ` Alan Maguire 2020-07-10 20:55 ` Andrii Nakryiko 1 sibling, 1 reply; 6+ messages in thread From: Alan Maguire @ 2020-07-10 14:22 UTC (permalink / raw) To: rostedt, mingo, ast, daniel, andriin Cc: kafai, songliubraving, yhs, john.fastabend, kpsingh, linux-kernel, netdev, bpf, Alan Maguire Simple selftests that verifies bpf_trace_printk() returns a sensible value and tracing messages appear. Signed-off-by: Alan Maguire <alan.maguire@oracle.com> --- .../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 ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour 2020-07-10 14:22 ` [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour Alan Maguire @ 2020-07-10 20:55 ` Andrii Nakryiko 0 siblings, 0 replies; 6+ messages in thread From: Andrii Nakryiko @ 2020-07-10 20:55 UTC (permalink / raw) To: Alan Maguire Cc: Steven Rostedt, Ingo Molnar, Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, Martin Lau, Song Liu, Yonghong Song, john fastabend, KP Singh, open list, Networking, bpf On Fri, Jul 10, 2020 at 7:25 AM Alan Maguire <alan.maguire@oracle.com> wrote: > > Simple selftests that verifies bpf_trace_printk() returns a sensible > value and tracing messages appear. > > Signed-off-by: Alan Maguire <alan.maguire@oracle.com> > --- see pedantic note below, but I don't think that's an issue in practice Acked-by: Andrii Nakryiko <andriin@fb.com> > .../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); > +} [...] ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2020-07-10 23:05 UTC | newest] Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2020-07-10 14:22 [PATCH v2 bpf-next 0/2] bpf: fix use of trace_printk() in BPF Alan Maguire 2020-07-10 14:22 ` [PATCH v2 bpf-next 1/2] bpf: use dedicated bpf_trace_printk event instead of trace_printk() Alan Maguire 2020-07-10 20:55 ` Andrii Nakryiko 2020-07-10 23:04 ` Daniel Borkmann 2020-07-10 14:22 ` [PATCH v2 bpf-next 2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour Alan Maguire 2020-07-10 20:55 ` Andrii Nakryiko
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).