[PATCH v3 bpf-next 0/7] bpf: implement variadic printk helper

[PATCH v3 bpf-next 0/7] bpf: implement variadic printk helper

[Dave Marchevsky]

This series introduces a new helper, bpf_trace_vprintk, which functions
like bpf_trace_printk but supports > 3 arguments via a pseudo-vararg u64
array. The bpf_printk libbpf convenience macro is modified to use
bpf_trace_vprintk when > 3 varargs are passed, otherwise the previous
behavior - using bpf_trace_printk - is retained.

Helper functions and macros added during the implementation of
bpf_seq_printf and bpf_snprintf do most of the heavy lifting for
bpf_trace_vprintk. There's no novel format string wrangling here.

Usecase here is straightforward: Giving BPF program writers a more
powerful printk will ease development of BPF programs, particularly
during debugging and testing, where printk tends to be used.

This feature was proposed by Andrii in libbpf mirror's issue tracker
[1].

[1] https://github.com/libbpf/libbpf/issues/315

v2 -> v3:
* Clean up patch 3's commit message [Alexei]
* Add patch 4, which modifies __bpf_printk to use 'static const char' to
  store fmt string with fallback for older kernels [Andrii]
* rebase

v1 -> v2:

* Naming conversation seems to have gone in favor of keeping
  bpf_trace_vprintk, names are unchanged

* Patch 3 now modifies bpf_printk convenience macro to choose between
  __bpf_printk and __bpf_vprintk 'implementation' macros based on arg
  count. __bpf_vprintk is a renaming of bpf_vprintk convenience macro
  from v1, __bpf_printk is the existing bpf_printk implementation.

  This patch could use some scrutiny as I think current implementation
  may regress developer experience in a specific case, turning a
  compile-time error into a load-time error. Unclear to me how
  common the case is, or whether the macro magic I chose is ideal.

* char ___fmt[] to static const char ___fmt[] change was not done,
  wanted to leave __bpf_printk 'implementation' macro unchanged for v2
  to ease discussion of above point

* Removed __always_inline from __set_printk_clr_event [Andrii]
* Simplified bpf_trace_printk docstring to refer to other functions
  instead of copy/pasting and avoid specifying 12 vararg limit [Andrii]
* Migrated trace_printk selftest to use ASSERT_ instead of CHECK
  * Adds new patch 5, previous patch 5 is now 6
* Migrated trace_vprintk selftest to use ASSERT_ instead of CHECK,
  open_and_load instead of separate open, load [Andrii]
* Patch 2's commit message now correctly mentions trace_pipe instead of
  dmesg [Andrii]

Dave Marchevsky (7):
  bpf: merge printk and seq_printf VARARG max macros
  bpf: add bpf_trace_vprintk helper
  libbpf: Modify bpf_printk to choose helper based on arg count
  libbpf: use static const fmt string in __bpf_printk
  bpftool: only probe trace_vprintk feature in 'full' mode
  selftests/bpf: Migrate prog_tests/trace_printk CHECKs to ASSERTs
  selftests/bpf: add trace_vprintk test prog

 include/linux/bpf.h                           |  3 +
 include/uapi/linux/bpf.h                      |  9 +++
 kernel/bpf/core.c                             |  5 ++
 kernel/bpf/helpers.c                          |  6 +-
 kernel/trace/bpf_trace.c                      | 54 ++++++++++++++-
 tools/bpf/bpftool/feature.c                   |  1 +
 tools/include/uapi/linux/bpf.h                |  9 +++
 tools/lib/bpf/bpf_helpers.h                   | 51 ++++++++++++---
 tools/testing/selftests/bpf/Makefile          |  3 +-
 .../selftests/bpf/prog_tests/trace_printk.c   | 24 +++----
 .../selftests/bpf/prog_tests/trace_vprintk.c  | 65 +++++++++++++++++++
 .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
 tools/testing/selftests/bpf/test_bpftool.py   | 22 +++----
 13 files changed, 234 insertions(+), 43 deletions(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
 create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c

-- 
2.30.2

[PATCH v3 bpf-next 1/7] bpf: merge printk and seq_printf VARARG max macros

[Dave Marchevsky]

MAX_SNPRINTF_VARARGS and MAX_SEQ_PRINTF_VARARGS are used by bpf helpers
bpf_snprintf and bpf_seq_printf to limit their varargs. Both call into
bpf_bprintf_prepare for print formatting logic and have convenience
macros in libbpf (BPF_SNPRINTF, BPF_SEQ_PRINTF) which use the same
helper macros to convert varargs to a byte array.

Changing shared functionality to support more varargs for either bpf
helper would affect the other as well, so let's combine the _VARARGS
macros to make this more obvious.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
---
 include/linux/bpf.h      | 2 ++
 kernel/bpf/helpers.c     | 4 +---
 kernel/trace/bpf_trace.c | 4 +---
 3 files changed, 4 insertions(+), 6 deletions(-)

diff --git a/include/linux/bpf.h b/include/linux/bpf.h
index f4c16f19f83e..be8d57e6e78a 100644
--- a/include/linux/bpf.h
+++ b/include/linux/bpf.h
@@ -2216,6 +2216,8 @@ int bpf_arch_text_poke(void *ip, enum bpf_text_poke_type t,
 struct btf_id_set;
 bool btf_id_set_contains(const struct btf_id_set *set, u32 id);
 
+#define MAX_BPRINTF_VARARGS		12
+
 int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
 			u32 **bin_buf, u32 num_args);
 void bpf_bprintf_cleanup(void);
diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
index c227b7d4f56c..0d969f8501e2 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c
@@ -969,15 +969,13 @@ int bpf_bprintf_prepare(char *fmt, u32 fmt_size, const u64 *raw_args,
 	return err;
 }
 
-#define MAX_SNPRINTF_VARARGS		12
-
 BPF_CALL_5(bpf_snprintf, char *, str, u32, str_size, char *, fmt,
 	   const void *, data, u32, data_len)
 {
 	int err, num_args;
 	u32 *bin_args;
 
-	if (data_len % 8 || data_len > MAX_SNPRINTF_VARARGS * 8 ||
+	if (data_len % 8 || data_len > MAX_BPRINTF_VARARGS * 8 ||
 	    (data_len && !data))
 		return -EINVAL;
 	num_args = data_len / 8;
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index 8e2eb950aa82..10672ebc63b7 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -414,15 +414,13 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
 	return &bpf_trace_printk_proto;
 }
 
-#define MAX_SEQ_PRINTF_VARARGS		12
-
 BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
 	   const void *, data, u32, data_len)
 {
 	int err, num_args;
 	u32 *bin_args;
 
-	if (data_len & 7 || data_len > MAX_SEQ_PRINTF_VARARGS * 8 ||
+	if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
 	    (data_len && !data))
 		return -EINVAL;
 	num_args = data_len / 8;
-- 
2.30.2

[PATCH v3 bpf-next 2/7] bpf: add bpf_trace_vprintk helper

[Dave Marchevsky]

This helper is meant to be "bpf_trace_printk, but with proper vararg
support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
array. Write to /sys/kernel/debug/tracing/trace_pipe using the same
mechanism as bpf_trace_printk.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 include/linux/bpf.h            |  1 +
 include/uapi/linux/bpf.h       |  9 ++++++
 kernel/bpf/core.c              |  5 ++++
 kernel/bpf/helpers.c           |  2 ++
 kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
 tools/include/uapi/linux/bpf.h |  9 ++++++
 6 files changed, 77 insertions(+), 1 deletion(-)

diff --git a/include/linux/bpf.h b/include/linux/bpf.h
index be8d57e6e78a..b6c45a6cbbba 100644
--- a/include/linux/bpf.h
+++ b/include/linux/bpf.h
@@ -1088,6 +1088,7 @@ bool bpf_prog_array_compatible(struct bpf_array *array, const struct bpf_prog *f
 int bpf_prog_calc_tag(struct bpf_prog *fp);
 
 const struct bpf_func_proto *bpf_get_trace_printk_proto(void);
+const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void);
 
 typedef unsigned long (*bpf_ctx_copy_t)(void *dst, const void *src,
 					unsigned long off, unsigned long len);
diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
index 791f31dd0abe..f171d4d33136 100644
--- a/include/uapi/linux/bpf.h
+++ b/include/uapi/linux/bpf.h
@@ -4877,6 +4877,14 @@ union bpf_attr {
  *		Get the struct pt_regs associated with **task**.
  *	Return
  *		A pointer to struct pt_regs.
+ *
+ * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
+ *	Description
+ *		Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
+ *		to format. Arguments are to be used as in **bpf_seq_printf**\ () helper.
+ *	Return
+ *		The number of bytes written to the buffer, or a negative error
+ *		in case of failure.
  */
 #define __BPF_FUNC_MAPPER(FN)		\
 	FN(unspec),			\
@@ -5055,6 +5063,7 @@ union bpf_attr {
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
 	FN(task_pt_regs),		\
+	FN(trace_vprintk),		\
 	/* */
 
 /* integer value in 'imm' field of BPF_CALL instruction selects which helper
diff --git a/kernel/bpf/core.c b/kernel/bpf/core.c
index 9f4636d021b1..6fddc13fe67f 100644
--- a/kernel/bpf/core.c
+++ b/kernel/bpf/core.c
@@ -2357,6 +2357,11 @@ const struct bpf_func_proto * __weak bpf_get_trace_printk_proto(void)
 	return NULL;
 }
 
+const struct bpf_func_proto * __weak bpf_get_trace_vprintk_proto(void)
+{
+	return NULL;
+}
+
 u64 __weak
 bpf_event_output(struct bpf_map *map, u64 flags, void *meta, u64 meta_size,
 		 void *ctx, u64 ctx_size, bpf_ctx_copy_t ctx_copy)
diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
index 0d969f8501e2..5f34f3dc7166 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c
@@ -1425,6 +1425,8 @@ bpf_base_func_proto(enum bpf_func_id func_id)
 		return &bpf_snprintf_proto;
 	case BPF_FUNC_task_pt_regs:
 		return &bpf_task_pt_regs_proto;
+	case BPF_FUNC_trace_vprintk:
+		return bpf_get_trace_vprintk_proto();
 	default:
 		return NULL;
 	}
diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index 10672ebc63b7..ea8358b0c748 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -398,7 +398,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
 	.arg2_type	= ARG_CONST_SIZE,
 };
 
-const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
+static void __set_printk_clr_event(void)
 {
 	/*
 	 * This program might be calling bpf_trace_printk,
@@ -410,10 +410,58 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
 	 */
 	if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
 		pr_warn_ratelimited("could not enable bpf_trace_printk events");
+}
 
+const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
+{
+	__set_printk_clr_event();
 	return &bpf_trace_printk_proto;
 }
 
+BPF_CALL_4(bpf_trace_vprintk, char *, fmt, u32, fmt_size, const void *, data,
+	   u32, data_len)
+{
+	static char buf[BPF_TRACE_PRINTK_SIZE];
+	unsigned long flags;
+	int ret, num_args;
+	u32 *bin_args;
+
+	if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
+	    (data_len && !data))
+		return -EINVAL;
+	num_args = data_len / 8;
+
+	ret = bpf_bprintf_prepare(fmt, fmt_size, data, &bin_args, num_args);
+	if (ret < 0)
+		return ret;
+
+	raw_spin_lock_irqsave(&trace_printk_lock, flags);
+	ret = bstr_printf(buf, sizeof(buf), fmt, bin_args);
+
+	trace_bpf_trace_printk(buf);
+	raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
+
+	bpf_bprintf_cleanup();
+
+	return ret;
+}
+
+static const struct bpf_func_proto bpf_trace_vprintk_proto = {
+	.func		= bpf_trace_vprintk,
+	.gpl_only	= true,
+	.ret_type	= RET_INTEGER,
+	.arg1_type	= ARG_PTR_TO_MEM,
+	.arg2_type	= ARG_CONST_SIZE,
+	.arg3_type	= ARG_PTR_TO_MEM_OR_NULL,
+	.arg4_type	= ARG_CONST_SIZE_OR_ZERO,
+};
+
+const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
+{
+	__set_printk_clr_event();
+	return &bpf_trace_vprintk_proto;
+}
+
 BPF_CALL_5(bpf_seq_printf, struct seq_file *, m, char *, fmt, u32, fmt_size,
 	   const void *, data, u32, data_len)
 {
@@ -1130,6 +1178,8 @@ bpf_tracing_func_proto(enum bpf_func_id func_id, const struct bpf_prog *prog)
 		return &bpf_snprintf_proto;
 	case BPF_FUNC_get_func_ip:
 		return &bpf_get_func_ip_proto_tracing;
+	case BPF_FUNC_trace_vprintk:
+		return bpf_get_trace_vprintk_proto();
 	default:
 		return bpf_base_func_proto(func_id);
 	}
diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
index 791f31dd0abe..f171d4d33136 100644
--- a/tools/include/uapi/linux/bpf.h
+++ b/tools/include/uapi/linux/bpf.h
@@ -4877,6 +4877,14 @@ union bpf_attr {
  *		Get the struct pt_regs associated with **task**.
  *	Return
  *		A pointer to struct pt_regs.
+ *
+ * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
+ *	Description
+ *		Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
+ *		to format. Arguments are to be used as in **bpf_seq_printf**\ () helper.
+ *	Return
+ *		The number of bytes written to the buffer, or a negative error
+ *		in case of failure.
  */
 #define __BPF_FUNC_MAPPER(FN)		\
 	FN(unspec),			\
@@ -5055,6 +5063,7 @@ union bpf_attr {
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
 	FN(task_pt_regs),		\
+	FN(trace_vprintk),		\
 	/* */
 
 /* integer value in 'imm' field of BPF_CALL instruction selects which helper
-- 
2.30.2

[PATCH v3 bpf-next 3/7] libbpf: Modify bpf_printk to choose helper based on arg count

[Dave Marchevsky]

Instead of being a thin wrapper which calls into bpf_trace_printk,
libbpf's bpf_printk convenience macro now chooses between
bpf_trace_printk and bpf_trace_vprintk. If the arg count (excluding
format string) is >3, use bpf_trace_vprintk, otherwise use the older
helper.

The motivation behind this added complexity - instead of migrating
entirely to bpf_trace_vprintk - is to maintain good developer experience
for users compiling against new libbpf but running on older kernels.
Users who are passing <=3 args to bpf_printk will see no change in their
bytecode.

__bpf_vprintk functions similarly to BPF_SEQ_PRINTF and BPF_SNPRINTF
macros elsewhere in the file - it allows use of bpf_trace_vprintk
without manual conversion of varargs to u64 array. Previous
implementation of bpf_printk macro is moved to __bpf_printk for use by
the new implementation.

This does change behavior of bpf_printk calls with >3 args in the "new
libbpf, old kernels" scenario. Before this patch, attempting to use 4
args to bpf_printk results in a compile-time error. After this patch,
using bpf_printk with 4 args results in a trace_vprintk helper call
being emitted and a load-time failure on older kernels.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/lib/bpf/bpf_helpers.h | 45 ++++++++++++++++++++++++++++++-------
 1 file changed, 37 insertions(+), 8 deletions(-)

diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
index b9987c3efa3c..5f087306cdfe 100644
--- a/tools/lib/bpf/bpf_helpers.h
+++ b/tools/lib/bpf/bpf_helpers.h
@@ -14,14 +14,6 @@
 #define __type(name, val) typeof(val) *name
 #define __array(name, val) typeof(val) *name[]
 
-/* Helper macro to print out debug messages */
-#define bpf_printk(fmt, ...)				\
-({							\
-	char ____fmt[] = fmt;				\
-	bpf_trace_printk(____fmt, sizeof(____fmt),	\
-			 ##__VA_ARGS__);		\
-})
-
 /*
  * Helper macro to place programs, maps, license in
  * different sections in elf_bpf file. Section names
@@ -224,4 +216,41 @@ enum libbpf_tristate {
 		     ___param, sizeof(___param));		\
 })
 
+/* Helper macro to print out debug messages */
+#define __bpf_printk(fmt, ...)				\
+({							\
+	char ____fmt[] = fmt;				\
+	bpf_trace_printk(____fmt, sizeof(____fmt),	\
+			 ##__VA_ARGS__);		\
+})
+
+/*
+ * __bpf_vprintk wraps the bpf_trace_vprintk helper with variadic arguments
+ * instead of an array of u64.
+ */
+#define __bpf_vprintk(fmt, args...)				\
+({								\
+	static const char ___fmt[] = fmt;			\
+	unsigned long long ___param[___bpf_narg(args)];		\
+								\
+	_Pragma("GCC diagnostic push")				\
+	_Pragma("GCC diagnostic ignored \"-Wint-conversion\"")	\
+	___bpf_fill(___param, args);				\
+	_Pragma("GCC diagnostic pop")				\
+								\
+	bpf_trace_vprintk(___fmt, sizeof(___fmt),		\
+		     ___param, sizeof(___param));		\
+})
+
+#define ___bpf_pick_printk(...) \
+	___bpf_nth(_, ##__VA_ARGS__, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,	\
+		__bpf_vprintk, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,		\
+		__bpf_vprintk, __bpf_vprintk, __bpf_printk, __bpf_printk,		\
+		__bpf_printk, __bpf_printk)
+
+#define bpf_printk(fmt, args...)		\
+({						\
+	___bpf_pick_printk(args)(fmt, args);	\
+})
+
 #endif
-- 
2.30.2

[PATCH v3 bpf-next 4/7] libbpf: use static const fmt string in __bpf_printk

[Dave Marchevsky]

The __bpf_printk convenience macro was using a 'char' fmt string holder
as it predates support for globals in libbpf. Move to more efficient
'static const char', but provide a fallback to the old way via
BPF_NO_GLOBAL_DATA so users on old kernels can still use the macro.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/lib/bpf/bpf_helpers.h | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
index 5f087306cdfe..a1d5ec6f285c 100644
--- a/tools/lib/bpf/bpf_helpers.h
+++ b/tools/lib/bpf/bpf_helpers.h
@@ -216,10 +216,16 @@ enum libbpf_tristate {
 		     ___param, sizeof(___param));		\
 })
 
+#ifdef BPF_NO_GLOBAL_DATA
+#define BPF_PRINTK_FMT_TYPE char
+#else
+#define BPF_PRINTK_FMT_TYPE static const char
+#endif
+
 /* Helper macro to print out debug messages */
 #define __bpf_printk(fmt, ...)				\
 ({							\
-	char ____fmt[] = fmt;				\
+	BPF_PRINTK_FMT_TYPE ____fmt[] = fmt;		\
 	bpf_trace_printk(____fmt, sizeof(____fmt),	\
 			 ##__VA_ARGS__);		\
 })
-- 
2.30.2

[PATCH v3 bpf-next 5/7] bpftool: only probe trace_vprintk feature in 'full' mode

[Dave Marchevsky]

Since commit 368cb0e7cdb5e ("bpftool: Make probes which emit dmesg
warnings optional"), some helpers aren't probed by bpftool unless
`full` arg is added to `bpftool feature probe`.

bpf_trace_vprintk can emit dmesg warnings when probed, so include it.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/bpf/bpftool/feature.c                 |  1 +
 tools/testing/selftests/bpf/test_bpftool.py | 22 +++++++++------------
 2 files changed, 10 insertions(+), 13 deletions(-)

diff --git a/tools/bpf/bpftool/feature.c b/tools/bpf/bpftool/feature.c
index 7f36385aa9e2..ade44577688e 100644
--- a/tools/bpf/bpftool/feature.c
+++ b/tools/bpf/bpftool/feature.c
@@ -624,6 +624,7 @@ probe_helpers_for_progtype(enum bpf_prog_type prog_type, bool supported_type,
 		 */
 		switch (id) {
 		case BPF_FUNC_trace_printk:
+		case BPF_FUNC_trace_vprintk:
 		case BPF_FUNC_probe_write_user:
 			if (!full_mode)
 				continue;
diff --git a/tools/testing/selftests/bpf/test_bpftool.py b/tools/testing/selftests/bpf/test_bpftool.py
index 4fed2dc25c0a..1c2408ee1f5d 100644
--- a/tools/testing/selftests/bpf/test_bpftool.py
+++ b/tools/testing/selftests/bpf/test_bpftool.py
@@ -57,6 +57,11 @@ def default_iface(f):
         return f(*args, iface, **kwargs)
     return wrapper
 
+DMESG_EMITTING_HELPERS = [
+        "bpf_probe_write_user",
+        "bpf_trace_printk",
+        "bpf_trace_vprintk",
+    ]
 
 class TestBpftool(unittest.TestCase):
     @classmethod
@@ -67,10 +72,7 @@ class TestBpftool(unittest.TestCase):
 
     @default_iface
     def test_feature_dev_json(self, iface):
-        unexpected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        unexpected_helpers = DMESG_EMITTING_HELPERS
         expected_keys = [
             "syscall_config",
             "program_types",
@@ -94,10 +96,7 @@ class TestBpftool(unittest.TestCase):
             bpftool_json(["feature", "probe"]),
             bpftool_json(["feature"]),
         ]
-        unexpected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        unexpected_helpers = DMESG_EMITTING_HELPERS
         expected_keys = [
             "syscall_config",
             "system_config",
@@ -121,10 +120,7 @@ class TestBpftool(unittest.TestCase):
             bpftool_json(["feature", "probe", "kernel", "full"]),
             bpftool_json(["feature", "probe", "full"]),
         ]
-        expected_helpers = [
-            "bpf_probe_write_user",
-            "bpf_trace_printk",
-        ]
+        expected_helpers = DMESG_EMITTING_HELPERS
 
         for tc in test_cases:
             # Check if expected helpers are included at least once in any
@@ -157,7 +153,7 @@ class TestBpftool(unittest.TestCase):
                 not_full_set.add(helper)
 
         self.assertCountEqual(full_set - not_full_set,
-                                {"bpf_probe_write_user", "bpf_trace_printk"})
+                              set(DMESG_EMITTING_HELPERS))
         self.assertCountEqual(not_full_set - full_set, set())
 
     def test_feature_macros(self):
-- 
2.30.2

[PATCH v3 bpf-next 6/7] selftests/bpf: Migrate prog_tests/trace_printk CHECKs to ASSERTs

[Dave Marchevsky]

Guidance for new tests is to use ASSERT macros instead of CHECK. Since
trace_vprintk test will borrow heavily from trace_printk's, migrate its
CHECKs so it remains obvious that the two are closely related.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 .../selftests/bpf/prog_tests/trace_printk.c   | 24 +++++++------------
 1 file changed, 9 insertions(+), 15 deletions(-)

diff --git a/tools/testing/selftests/bpf/prog_tests/trace_printk.c b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
index d39bc00feb45..e47835f0a674 100644
--- a/tools/testing/selftests/bpf/prog_tests/trace_printk.c
+++ b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
@@ -10,7 +10,7 @@
 
 void test_trace_printk(void)
 {
-	int err, iter = 0, duration = 0, found = 0;
+	int err = 0, iter = 0, found = 0;
 	struct trace_printk__bss *bss;
 	struct trace_printk *skel;
 	char *buf = NULL;
@@ -18,25 +18,24 @@ void test_trace_printk(void)
 	size_t buflen;
 
 	skel = trace_printk__open();
-	if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
+	if (!ASSERT_OK_PTR(skel, "trace_printk__open"))
 		return;
 
-	ASSERT_EQ(skel->rodata->fmt[0], 'T', "invalid printk fmt string");
+	ASSERT_EQ(skel->rodata->fmt[0], 'T', "skel->rodata->fmt[0]");
 	skel->rodata->fmt[0] = 't';
 
 	err = trace_printk__load(skel);
-	if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))
+	if (!ASSERT_OK(err, "trace_printk__load"))
 		goto cleanup;
 
 	bss = skel->bss;
 
 	err = trace_printk__attach(skel);
-	if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
+	if (!ASSERT_OK(err, "trace_printk__attach"))
 		goto cleanup;
 
 	fp = fopen(TRACEBUF, "r");
-	if (CHECK(fp == NULL, "could not open trace buffer",
-		  "error %d opening %s", errno, TRACEBUF))
+	if (!ASSERT_OK_PTR(fp, "fopen(TRACEBUF)"))
 		goto cleanup;
 
 	/* We do not want to wait forever if this test fails... */
@@ -46,14 +45,10 @@ void test_trace_printk(void)
 	usleep(1);
 	trace_printk__detach(skel);
 
-	if (CHECK(bss->trace_printk_ran == 0,
-		  "bpf_trace_printk never ran",
-		  "ran == %d", bss->trace_printk_ran))
+	if (!ASSERT_GT(bss->trace_printk_ran, 0, "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))
+	if (!ASSERT_GT(bss->trace_printk_ret, 0, "bss->trace_printk_ret"))
 		goto cleanup;
 
 	/* verify our search string is in the trace buffer */
@@ -66,8 +61,7 @@ void test_trace_printk(void)
 			break;
 	}
 
-	if (CHECK(!found, "message from bpf_trace_printk not found",
-		  "no instance of %s in %s", SEARCHMSG, TRACEBUF))
+	if (!ASSERT_EQ(found, bss->trace_printk_ran, "found"))
 		goto cleanup;
 
 cleanup:
-- 
2.30.2

[PATCH v3 bpf-next 7/7] selftests/bpf: add trace_vprintk test prog

[Dave Marchevsky]

This commit adds a test prog for vprintk which confirms that:
  * bpf_trace_vprintk is writing to dmesg
  * __bpf_vprintk macro works as expected
  * >3 args are printed

Approach and code are borrowed from trace_printk test.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 tools/testing/selftests/bpf/Makefile          |  3 +-
 .../selftests/bpf/prog_tests/trace_vprintk.c  | 65 +++++++++++++++++++
 .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
 3 files changed, 92 insertions(+), 1 deletion(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
 create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c

diff --git a/tools/testing/selftests/bpf/Makefile b/tools/testing/selftests/bpf/Makefile
index 866531c08e4f..0a4cdac7ea02 100644
--- a/tools/testing/selftests/bpf/Makefile
+++ b/tools/testing/selftests/bpf/Makefile
@@ -315,7 +315,8 @@ LINKED_SKELS := test_static_linked.skel.h linked_funcs.skel.h		\
 		linked_vars.skel.h linked_maps.skel.h
 
 LSKELS := kfunc_call_test.c fentry_test.c fexit_test.c fexit_sleep.c \
-	test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c
+	test_ksyms_module.c test_ringbuf.c atomics.c trace_printk.c \
+	trace_vprintk.c
 SKEL_BLACKLIST += $$(LSKELS)
 
 test_static_linked.skel.h-deps := test_static_linked1.o test_static_linked2.o
diff --git a/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
new file mode 100644
index 000000000000..9fc1d279b673
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
@@ -0,0 +1,65 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2021 Facebook */
+
+#include <test_progs.h>
+
+#include "trace_vprintk.lskel.h"
+
+#define TRACEBUF	"/sys/kernel/debug/tracing/trace_pipe"
+#define SEARCHMSG	"1,2,3,4,5,6,7,8,9,10"
+
+void test_trace_vprintk(void)
+{
+	int err = 0, iter = 0, found = 0;
+	struct trace_vprintk__bss *bss;
+	struct trace_vprintk *skel;
+	char *buf = NULL;
+	FILE *fp = NULL;
+	size_t buflen;
+
+	skel = trace_vprintk__open_and_load();
+	if (!ASSERT_OK_PTR(skel, "trace_vprintk__open_and_load"))
+		goto cleanup;
+
+	bss = skel->bss;
+
+	err = trace_vprintk__attach(skel);
+	if (!ASSERT_OK(err, "trace_vprintk__attach"))
+		goto cleanup;
+
+	fp = fopen(TRACEBUF, "r");
+	if (!ASSERT_OK_PTR(fp, "fopen(TRACEBUF)"))
+		goto cleanup;
+
+	/* We do not want to wait forever if this test fails... */
+	fcntl(fileno(fp), F_SETFL, O_NONBLOCK);
+
+	/* wait for tracepoint to trigger */
+	usleep(1);
+	trace_vprintk__detach(skel);
+
+	if (!ASSERT_GT(bss->trace_vprintk_ran, 0, "bss->trace_vprintk_ran"))
+		goto cleanup;
+
+	if (!ASSERT_GT(bss->trace_vprintk_ret, 0, "bss->trace_vprintk_ret"))
+		goto cleanup;
+
+	/* verify our search string is in the trace buffer */
+	while (getline(&buf, &buflen, fp) >= 0 || errno == EAGAIN) {
+		if (strstr(buf, SEARCHMSG) != NULL)
+			found++;
+		if (found == bss->trace_vprintk_ran)
+			break;
+		if (++iter > 1000)
+			break;
+	}
+
+	if (!ASSERT_EQ(found, bss->trace_vprintk_ran, "found"))
+		goto cleanup;
+
+cleanup:
+	trace_vprintk__destroy(skel);
+	free(buf);
+	if (fp)
+		fclose(fp);
+}
diff --git a/tools/testing/selftests/bpf/progs/trace_vprintk.c b/tools/testing/selftests/bpf/progs/trace_vprintk.c
new file mode 100644
index 000000000000..255e2f018efe
--- /dev/null
+++ b/tools/testing/selftests/bpf/progs/trace_vprintk.c
@@ -0,0 +1,25 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2021 Facebook */
+
+#include "vmlinux.h"
+#include <bpf/bpf_helpers.h>
+#include <bpf/bpf_tracing.h>
+
+char _license[] SEC("license") = "GPL";
+
+int trace_vprintk_ret = 0;
+int trace_vprintk_ran = 0;
+
+SEC("fentry/__x64_sys_nanosleep")
+int sys_enter(void *ctx)
+{
+	static const char one[] = "1";
+	static const char three[] = "3";
+	static const char five[] = "5";
+	static const char seven[] = "7";
+	static const char nine[] = "9";
+
+	trace_vprintk_ret = __bpf_vprintk("%s,%d,%s,%d,%s,%d,%s,%d,%s,%d %d\n",
+		one, 2, three, 4, five, 6, seven, 8, nine, 10, ++trace_vprintk_ran);
+	return 0;
+}
-- 
2.30.2

Re: [PATCH v3 bpf-next 4/7] libbpf: use static const fmt string in __bpf_printk

[Dave Marchevsky]

On 8/28/21 1:20 AM, Dave Marchevsky wrote:   
> The __bpf_printk convenience macro was using a 'char' fmt string holder
> as it predates support for globals in libbpf. Move to more efficient
> 'static const char', but provide a fallback to the old way via
> BPF_NO_GLOBAL_DATA so users on old kernels can still use the macro.
> 
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  tools/lib/bpf/bpf_helpers.h | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> index 5f087306cdfe..a1d5ec6f285c 100644
> --- a/tools/lib/bpf/bpf_helpers.h
> +++ b/tools/lib/bpf/bpf_helpers.h
> @@ -216,10 +216,16 @@ enum libbpf_tristate {
>  		     ___param, sizeof(___param));		\
>  })
>  
> +#ifdef BPF_NO_GLOBAL_DATA
> +#define BPF_PRINTK_FMT_TYPE char
> +#else
> +#define BPF_PRINTK_FMT_TYPE static const char

The reference_tracking prog test is failing as a result of this.
Specifically, it fails to load bpf_sk_lookup_test0 prog, which 
has a bpf_printk:

  47: (b4) w3 = 0
  48: (18) r1 = 0x0
  50: (b4) w2 = 7
  51: (85) call bpf_trace_printk#6
  R1 type=inv expected=fp, pkt, pkt_meta, map_key, map_value, mem, rdonly_buf, rdwr_buf

Setting BPF_NO_GLOBAL_DATA in the test results in a pass

> +#endif
> +
>  /* Helper macro to print out debug messages */
>  #define __bpf_printk(fmt, ...)				\
>  ({							\
> -	char ____fmt[] = fmt;				\
> +	BPF_PRINTK_FMT_TYPE ____fmt[] = fmt;		\
>  	bpf_trace_printk(____fmt, sizeof(____fmt),	\
>  			 ##__VA_ARGS__);		\
>  })
> 

Re: [PATCH v3 bpf-next 3/7] libbpf: Modify bpf_printk to choose helper based on arg count

[Dave Marchevsky]

On 8/28/21 1:20 AM, Dave Marchevsky wrote:   
> Instead of being a thin wrapper which calls into bpf_trace_printk,
> libbpf's bpf_printk convenience macro now chooses between
> bpf_trace_printk and bpf_trace_vprintk. If the arg count (excluding
> format string) is >3, use bpf_trace_vprintk, otherwise use the older
> helper.
> 
> The motivation behind this added complexity - instead of migrating
> entirely to bpf_trace_vprintk - is to maintain good developer experience
> for users compiling against new libbpf but running on older kernels.
> Users who are passing <=3 args to bpf_printk will see no change in their
> bytecode.
> 
> __bpf_vprintk functions similarly to BPF_SEQ_PRINTF and BPF_SNPRINTF
> macros elsewhere in the file - it allows use of bpf_trace_vprintk
> without manual conversion of varargs to u64 array. Previous
> implementation of bpf_printk macro is moved to __bpf_printk for use by
> the new implementation.
> 
> This does change behavior of bpf_printk calls with >3 args in the "new
> libbpf, old kernels" scenario. Before this patch, attempting to use 4
> args to bpf_printk results in a compile-time error. After this patch,
> using bpf_printk with 4 args results in a trace_vprintk helper call
> being emitted and a load-time failure on older kernels.
> 
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  tools/lib/bpf/bpf_helpers.h | 45 ++++++++++++++++++++++++++++++-------
>  1 file changed, 37 insertions(+), 8 deletions(-)
> 
> diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> index b9987c3efa3c..5f087306cdfe 100644
> --- a/tools/lib/bpf/bpf_helpers.h
> +++ b/tools/lib/bpf/bpf_helpers.h
> @@ -14,14 +14,6 @@
>  #define __type(name, val) typeof(val) *name
>  #define __array(name, val) typeof(val) *name[]
>  
> -/* Helper macro to print out debug messages */
> -#define bpf_printk(fmt, ...)				\
> -({							\
> -	char ____fmt[] = fmt;				\
> -	bpf_trace_printk(____fmt, sizeof(____fmt),	\
> -			 ##__VA_ARGS__);		\
> -})
> -
>  /*
>   * Helper macro to place programs, maps, license in
>   * different sections in elf_bpf file. Section names
> @@ -224,4 +216,41 @@ enum libbpf_tristate {
>  		     ___param, sizeof(___param));		\
>  })
>  
> +/* Helper macro to print out debug messages */
> +#define __bpf_printk(fmt, ...)				\
> +({							\
> +	char ____fmt[] = fmt;				\
> +	bpf_trace_printk(____fmt, sizeof(____fmt),	\
> +			 ##__VA_ARGS__);		\
> +})
> +
> +/*
> + * __bpf_vprintk wraps the bpf_trace_vprintk helper with variadic arguments
> + * instead of an array of u64.
> + */
> +#define __bpf_vprintk(fmt, args...)				\
> +({								\
> +	static const char ___fmt[] = fmt;			\
> +	unsigned long long ___param[___bpf_narg(args)];		\
> +								\
> +	_Pragma("GCC diagnostic push")				\
> +	_Pragma("GCC diagnostic ignored \"-Wint-conversion\"")	\
> +	___bpf_fill(___param, args);				\
> +	_Pragma("GCC diagnostic pop")				\
> +								\
> +	bpf_trace_vprintk(___fmt, sizeof(___fmt),		\
> +		     ___param, sizeof(___param));		\
> +})
> +
> +#define ___bpf_pick_printk(...) \
> +	___bpf_nth(_, ##__VA_ARGS__, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,	\
> +		__bpf_vprintk, __bpf_vprintk, __bpf_vprintk, __bpf_vprintk,		\
> +		__bpf_vprintk, __bpf_vprintk, __bpf_printk, __bpf_printk,		\
> +		__bpf_printk, __bpf_printk)
> +
> +#define bpf_printk(fmt, args...)		\
> +({						\
> +	___bpf_pick_printk(args)(fmt, args);	\

While looking at test failure related to patch 4, noticed
that this isn't handling 0 format arg case correctly, resulting
in compilation error.

Need to fix and add a test as all extant selftests are doing
bpf_printk with at least 1 format arg.

> +})
> +
>  #endif
> 

Re: [PATCH v3 bpf-next 4/7] libbpf: use static const fmt string in __bpf_printk

[Alexei Starovoitov]

On Sat, Aug 28, 2021 at 12:40:17PM -0400, Dave Marchevsky wrote:
> On 8/28/21 1:20 AM, Dave Marchevsky wrote:   
> > The __bpf_printk convenience macro was using a 'char' fmt string holder
> > as it predates support for globals in libbpf. Move to more efficient
> > 'static const char', but provide a fallback to the old way via
> > BPF_NO_GLOBAL_DATA so users on old kernels can still use the macro.
> > 
> > Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> > ---
> >  tools/lib/bpf/bpf_helpers.h | 8 +++++++-
> >  1 file changed, 7 insertions(+), 1 deletion(-)
> > 
> > diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> > index 5f087306cdfe..a1d5ec6f285c 100644
> > --- a/tools/lib/bpf/bpf_helpers.h
> > +++ b/tools/lib/bpf/bpf_helpers.h
> > @@ -216,10 +216,16 @@ enum libbpf_tristate {
> >  		     ___param, sizeof(___param));		\
> >  })
> >  
> > +#ifdef BPF_NO_GLOBAL_DATA
> > +#define BPF_PRINTK_FMT_TYPE char
> > +#else
> > +#define BPF_PRINTK_FMT_TYPE static const char
> 
> The reference_tracking prog test is failing as a result of this.
> Specifically, it fails to load bpf_sk_lookup_test0 prog, which 
> has a bpf_printk:
> 
>   47: (b4) w3 = 0
>   48: (18) r1 = 0x0
>   50: (b4) w2 = 7
>   51: (85) call bpf_trace_printk#6
>   R1 type=inv expected=fp, pkt, pkt_meta, map_key, map_value, mem, rdonly_buf, rdwr_buf
> 
> Setting BPF_NO_GLOBAL_DATA in the test results in a pass

hmm. that's odd. pls investigate.
Worst case we can just drop this patch for now.
The failing printk is this one, right?
bpf_printk("sk=%d\n", sk ? 1 : 0);
iirc we had an issue related to ?: operand being used as an argument
and llvm generating interesting code path with 'sk' and the later
if (sk) bpf_sk_release(sk);
would not be properly recognized by the verifier leading it to
believe that sk may not be released in some cases.
That printk was triggering such interesting llvm codegen.
See commit d844a71bff0f ("bpf: Selftests, add printk to test_sk_lookup_kern to encode null ptr check")

Re: [PATCH v3 bpf-next 2/7] bpf: add bpf_trace_vprintk helper

[Andrii Nakryiko]

On Fri, Aug 27, 2021 at 10:20 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> This helper is meant to be "bpf_trace_printk, but with proper vararg
> support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> array. Write to /sys/kernel/debug/tracing/trace_pipe using the same
> mechanism as bpf_trace_printk.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---

LGTM.

Acked-by: Andrii Nakryiko <andrii@kernel.org>

>  include/linux/bpf.h            |  1 +
>  include/uapi/linux/bpf.h       |  9 ++++++
>  kernel/bpf/core.c              |  5 ++++
>  kernel/bpf/helpers.c           |  2 ++
>  kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
>  tools/include/uapi/linux/bpf.h |  9 ++++++
>  6 files changed, 77 insertions(+), 1 deletion(-)
>

[...]

Re: [PATCH v3 bpf-next 6/7] selftests/bpf: Migrate prog_tests/trace_printk CHECKs to ASSERTs

[Andrii Nakryiko]

On Fri, Aug 27, 2021 at 10:20 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> Guidance for new tests is to use ASSERT macros instead of CHECK. Since
> trace_vprintk test will borrow heavily from trace_printk's, migrate its
> CHECKs so it remains obvious that the two are closely related.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---

Great, thanks!

Acked-by: Andrii Nakryiko <andrii@kernel.org>

>  .../selftests/bpf/prog_tests/trace_printk.c   | 24 +++++++------------
>  1 file changed, 9 insertions(+), 15 deletions(-)
>
> diff --git a/tools/testing/selftests/bpf/prog_tests/trace_printk.c b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
> index d39bc00feb45..e47835f0a674 100644
> --- a/tools/testing/selftests/bpf/prog_tests/trace_printk.c
> +++ b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
> @@ -10,7 +10,7 @@
>
>  void test_trace_printk(void)
>  {
> -       int err, iter = 0, duration = 0, found = 0;
> +       int err = 0, iter = 0, found = 0;
>         struct trace_printk__bss *bss;
>         struct trace_printk *skel;
>         char *buf = NULL;
> @@ -18,25 +18,24 @@ void test_trace_printk(void)
>         size_t buflen;
>
>         skel = trace_printk__open();
> -       if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
> +       if (!ASSERT_OK_PTR(skel, "trace_printk__open"))
>                 return;
>
> -       ASSERT_EQ(skel->rodata->fmt[0], 'T', "invalid printk fmt string");
> +       ASSERT_EQ(skel->rodata->fmt[0], 'T', "skel->rodata->fmt[0]");
>         skel->rodata->fmt[0] = 't';
>
>         err = trace_printk__load(skel);
> -       if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))
> +       if (!ASSERT_OK(err, "trace_printk__load"))
>                 goto cleanup;
>
>         bss = skel->bss;
>
>         err = trace_printk__attach(skel);
> -       if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
> +       if (!ASSERT_OK(err, "trace_printk__attach"))
>                 goto cleanup;
>
>         fp = fopen(TRACEBUF, "r");
> -       if (CHECK(fp == NULL, "could not open trace buffer",
> -                 "error %d opening %s", errno, TRACEBUF))
> +       if (!ASSERT_OK_PTR(fp, "fopen(TRACEBUF)"))
>                 goto cleanup;
>
>         /* We do not want to wait forever if this test fails... */
> @@ -46,14 +45,10 @@ void test_trace_printk(void)
>         usleep(1);
>         trace_printk__detach(skel);
>
> -       if (CHECK(bss->trace_printk_ran == 0,
> -                 "bpf_trace_printk never ran",
> -                 "ran == %d", bss->trace_printk_ran))
> +       if (!ASSERT_GT(bss->trace_printk_ran, 0, "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))
> +       if (!ASSERT_GT(bss->trace_printk_ret, 0, "bss->trace_printk_ret"))
>                 goto cleanup;
>
>         /* verify our search string is in the trace buffer */
> @@ -66,8 +61,7 @@ void test_trace_printk(void)
>                         break;
>         }
>
> -       if (CHECK(!found, "message from bpf_trace_printk not found",
> -                 "no instance of %s in %s", SEARCHMSG, TRACEBUF))
> +       if (!ASSERT_EQ(found, bss->trace_printk_ran, "found"))
>                 goto cleanup;
>
>  cleanup:
> --
> 2.30.2
>

Re: [PATCH v3 bpf-next 7/7] selftests/bpf: add trace_vprintk test prog

[Andrii Nakryiko]

On Fri, Aug 27, 2021 at 10:20 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> This commit adds a test prog for vprintk which confirms that:
>   * bpf_trace_vprintk is writing to dmesg
>   * __bpf_vprintk macro works as expected
>   * >3 args are printed
>
> Approach and code are borrowed from trace_printk test.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---

LGTM.

Acked-by: Andrii Nakryiko <andrii@kernel.org>

>  tools/testing/selftests/bpf/Makefile          |  3 +-
>  .../selftests/bpf/prog_tests/trace_vprintk.c  | 65 +++++++++++++++++++
>  .../selftests/bpf/progs/trace_vprintk.c       | 25 +++++++
>  3 files changed, 92 insertions(+), 1 deletion(-)
>  create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_vprintk.c
>  create mode 100644 tools/testing/selftests/bpf/progs/trace_vprintk.c
>

[...]

Re: [PATCH v3 bpf-next 4/7] libbpf: use static const fmt string in __bpf_printk

[Andrii Nakryiko]

On Sun, Aug 29, 2021 at 9:57 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Sat, Aug 28, 2021 at 12:40:17PM -0400, Dave Marchevsky wrote:
> > On 8/28/21 1:20 AM, Dave Marchevsky wrote:
> > > The __bpf_printk convenience macro was using a 'char' fmt string holder
> > > as it predates support for globals in libbpf. Move to more efficient
> > > 'static const char', but provide a fallback to the old way via
> > > BPF_NO_GLOBAL_DATA so users on old kernels can still use the macro.
> > >
> > > Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> > > ---
> > >  tools/lib/bpf/bpf_helpers.h | 8 +++++++-
> > >  1 file changed, 7 insertions(+), 1 deletion(-)
> > >
> > > diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> > > index 5f087306cdfe..a1d5ec6f285c 100644
> > > --- a/tools/lib/bpf/bpf_helpers.h
> > > +++ b/tools/lib/bpf/bpf_helpers.h
> > > @@ -216,10 +216,16 @@ enum libbpf_tristate {
> > >                  ___param, sizeof(___param));               \
> > >  })
> > >
> > > +#ifdef BPF_NO_GLOBAL_DATA
> > > +#define BPF_PRINTK_FMT_TYPE char
> > > +#else
> > > +#define BPF_PRINTK_FMT_TYPE static const char
> >
> > The reference_tracking prog test is failing as a result of this.
> > Specifically, it fails to load bpf_sk_lookup_test0 prog, which
> > has a bpf_printk:
> >
> >   47: (b4) w3 = 0
> >   48: (18) r1 = 0x0
> >   50: (b4) w2 = 7
> >   51: (85) call bpf_trace_printk#6
> >   R1 type=inv expected=fp, pkt, pkt_meta, map_key, map_value, mem, rdonly_buf, rdwr_buf
> >
> > Setting BPF_NO_GLOBAL_DATA in the test results in a pass
>
> hmm. that's odd. pls investigate.

It's a broken reference_tracking selftest which uses direct calls into
bpf_program__load() API, which is not supposed to be used directly. In
this case bpf_program__load() doesn't apply any relocation for
.rodata, so verifier rightfully complains that constant zero is not
really a valid pointer to memory. It's a plan for libbpf 1.0 to hide
bpf_program__load() (which is supposed to be used only internally by
libbpf). And it's surprising that we have a test using that API
directly, it somehow slipped by us.

Dave, can you please switch this selftest to use bpf_object__load()
properly? This seems to be the only selftests that's using
bpf_program__load(). You'll probably need to open/iterate
programs/bpf_progam__set_autoload() properly based on
name/bpf_object__load() in a loop for each BPF prog to be tested.


> Worst case we can just drop this patch for now.
> The failing printk is this one, right?
> bpf_printk("sk=%d\n", sk ? 1 : 0);
> iirc we had an issue related to ?: operand being used as an argument
> and llvm generating interesting code path with 'sk' and the later
> if (sk) bpf_sk_release(sk);
> would not be properly recognized by the verifier leading it to
> believe that sk may not be released in some cases.
> That printk was triggering such interesting llvm codegen.
> See commit d844a71bff0f ("bpf: Selftests, add printk to test_sk_lookup_kern to encode null ptr check")

Re: [PATCH v3 bpf-next 4/7] libbpf: use static const fmt string in __bpf_printk

[Andrii Nakryiko]

On Fri, Aug 27, 2021 at 10:20 PM Dave Marchevsky <davemarchevsky@fb.com> wrote:
>
> The __bpf_printk convenience macro was using a 'char' fmt string holder
> as it predates support for globals in libbpf. Move to more efficient
> 'static const char', but provide a fallback to the old way via
> BPF_NO_GLOBAL_DATA so users on old kernels can still use the macro.
>
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>  tools/lib/bpf/bpf_helpers.h | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
>
> diff --git a/tools/lib/bpf/bpf_helpers.h b/tools/lib/bpf/bpf_helpers.h
> index 5f087306cdfe..a1d5ec6f285c 100644
> --- a/tools/lib/bpf/bpf_helpers.h
> +++ b/tools/lib/bpf/bpf_helpers.h
> @@ -216,10 +216,16 @@ enum libbpf_tristate {
>                      ___param, sizeof(___param));               \
>  })
>
> +#ifdef BPF_NO_GLOBAL_DATA
> +#define BPF_PRINTK_FMT_TYPE char
> +#else
> +#define BPF_PRINTK_FMT_TYPE static const char
> +#endif
> +
>  /* Helper macro to print out debug messages */
>  #define __bpf_printk(fmt, ...)                         \
>  ({                                                     \
> -       char ____fmt[] = fmt;                           \
> +       BPF_PRINTK_FMT_TYPE ____fmt[] = fmt;            \

personal preferences, of course, but I'd leave char right there (I
think it makes it a bit more obvious what's going on right there), and
s/BPF_PRINTK_FMT_TYPE/BPF_PRINTK_FMT_MOD/ and have it as either "" or
"static const".

>         bpf_trace_printk(____fmt, sizeof(____fmt),      \
>                          ##__VA_ARGS__);                \
>  })
> --
> 2.30.2
>

Re: [PATCH v3 bpf-next 2/7] bpf: add bpf_trace_vprintk helper

[Daniel Borkmann]

On 8/28/21 7:20 AM, Dave Marchevsky wrote:
> This helper is meant to be "bpf_trace_printk, but with proper vararg
> support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
> array. Write to /sys/kernel/debug/tracing/trace_pipe using the same
> mechanism as bpf_trace_printk.
> 
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>

lgtm, minor comments below:

> ---
>   include/linux/bpf.h            |  1 +
>   include/uapi/linux/bpf.h       |  9 ++++++
>   kernel/bpf/core.c              |  5 ++++
>   kernel/bpf/helpers.c           |  2 ++
>   kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
>   tools/include/uapi/linux/bpf.h |  9 ++++++
>   6 files changed, 77 insertions(+), 1 deletion(-)
> 
> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
> index be8d57e6e78a..b6c45a6cbbba 100644
> --- a/include/linux/bpf.h
> +++ b/include/linux/bpf.h
> @@ -1088,6 +1088,7 @@ bool bpf_prog_array_compatible(struct bpf_array *array, const struct bpf_prog *f
>   int bpf_prog_calc_tag(struct bpf_prog *fp);
>   
>   const struct bpf_func_proto *bpf_get_trace_printk_proto(void);
> +const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void);
>   
>   typedef unsigned long (*bpf_ctx_copy_t)(void *dst, const void *src,
>   					unsigned long off, unsigned long len);
> diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
> index 791f31dd0abe..f171d4d33136 100644
> --- a/include/uapi/linux/bpf.h
> +++ b/include/uapi/linux/bpf.h
> @@ -4877,6 +4877,14 @@ union bpf_attr {
>    *		Get the struct pt_regs associated with **task**.
>    *	Return
>    *		A pointer to struct pt_regs.
> + *
> + * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)

s/u64/long/

> + *	Description
> + *		Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64

nit: maybe for users it's more clear from description if you instead mention that data_len
needs to be multiple of 8 bytes? Or somehow mention the relation with data more clearly
resp. which shortcoming it addresses compared to bpf_trace_printk(), so developers can more
easily parse it.

> + *		to format. Arguments are to be used as in **bpf_seq_printf**\ () helper.
> + *	Return
> + *		The number of bytes written to the buffer, or a negative error
> + *		in case of failure.
>    */
[...]
>   	default:
>   		return NULL;
>   	}
> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index 10672ebc63b7..ea8358b0c748 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -398,7 +398,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
>   	.arg2_type	= ARG_CONST_SIZE,
>   };
>   
> -const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
> +static void __set_printk_clr_event(void)
>   {
>   	/*
>   	 * This program might be calling bpf_trace_printk,
> @@ -410,10 +410,58 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>   	 */
>   	if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
>   		pr_warn_ratelimited("could not enable bpf_trace_printk events");
> +}
>   
> +const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
> +{
> +	__set_printk_clr_event();
>   	return &bpf_trace_printk_proto;
>   }
>   
> +BPF_CALL_4(bpf_trace_vprintk, char *, fmt, u32, fmt_size, const void *, data,
> +	   u32, data_len)
> +{
> +	static char buf[BPF_TRACE_PRINTK_SIZE];
> +	unsigned long flags;
> +	int ret, num_args;
> +	u32 *bin_args;
> +
> +	if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
> +	    (data_len && !data))
> +		return -EINVAL;
> +	num_args = data_len / 8;
> +
> +	ret = bpf_bprintf_prepare(fmt, fmt_size, data, &bin_args, num_args);
> +	if (ret < 0)
> +		return ret;

Given you have ARG_PTR_TO_MEM_OR_NULL for data, does this gracefully handle the
case where you pass in fmt string containing e.g. %ps but data being NULL? From
reading bpf_bprintf_prepare() looks like it does just fine, but might be nice
to explicitly add a tiny selftest case for it while you're at it.

> +	raw_spin_lock_irqsave(&trace_printk_lock, flags);
> +	ret = bstr_printf(buf, sizeof(buf), fmt, bin_args);
> +
> +	trace_bpf_trace_printk(buf);
> +	raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
> +
> +	bpf_bprintf_cleanup();
> +
> +	return ret;
> +}

Thanks,
Daniel

Re: [PATCH v3 bpf-next 2/7] bpf: add bpf_trace_vprintk helper

[Dave Marchevsky]

On 9/3/21 4:00 AM, Daniel Borkmann wrote:   
> On 8/28/21 7:20 AM, Dave Marchevsky wrote:
>> This helper is meant to be "bpf_trace_printk, but with proper vararg
>> support". Follow bpf_snprintf's example and take a u64 pseudo-vararg
>> array. Write to /sys/kernel/debug/tracing/trace_pipe using the same
>> mechanism as bpf_trace_printk.
>>
>> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> 
> lgtm, minor comments below:
> 
>> ---
>>   include/linux/bpf.h            |  1 +
>>   include/uapi/linux/bpf.h       |  9 ++++++
>>   kernel/bpf/core.c              |  5 ++++
>>   kernel/bpf/helpers.c           |  2 ++
>>   kernel/trace/bpf_trace.c       | 52 +++++++++++++++++++++++++++++++++-
>>   tools/include/uapi/linux/bpf.h |  9 ++++++
>>   6 files changed, 77 insertions(+), 1 deletion(-)
>>
>> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
>> index be8d57e6e78a..b6c45a6cbbba 100644
>> --- a/include/linux/bpf.h
>> +++ b/include/linux/bpf.h
>> @@ -1088,6 +1088,7 @@ bool bpf_prog_array_compatible(struct bpf_array *array, const struct bpf_prog *f
>>   int bpf_prog_calc_tag(struct bpf_prog *fp);
>>     const struct bpf_func_proto *bpf_get_trace_printk_proto(void);
>> +const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void);
>>     typedef unsigned long (*bpf_ctx_copy_t)(void *dst, const void *src,
>>                       unsigned long off, unsigned long len);
>> diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
>> index 791f31dd0abe..f171d4d33136 100644
>> --- a/include/uapi/linux/bpf.h
>> +++ b/include/uapi/linux/bpf.h
>> @@ -4877,6 +4877,14 @@ union bpf_attr {
>>    *        Get the struct pt_regs associated with **task**.
>>    *    Return
>>    *        A pointer to struct pt_regs.
>> + *
>> + * u64 bpf_trace_vprintk(const char *fmt, u32 fmt_size, const void *data, u32 data_len)
> 
> s/u64/long/
> 
>> + *    Description
>> + *        Behaves like **bpf_trace_printk**\ () helper, but takes an array of u64
> 
> nit: maybe for users it's more clear from description if you instead mention that data_len
> needs to be multiple of 8 bytes? Or somehow mention the relation with data more clearly
> resp. which shortcoming it addresses compared to bpf_trace_printk(), so developers can more
> easily parse it.

In a previous review pass, Andrii preferred having bpf_trace_vprintk's reference other helpers
instead of copy/pasting. So in v5 (patch 9) of this patchset I've added "multiple of 8 bytes"
to helper comments for bpf_seq_printf and bpf_snprintf. Added a sentence mentioning benefits
of vprintk over printk in v5 (patch 3).

>> + *        to format. Arguments are to be used as in **bpf_seq_printf**\ () helper.
>> + *    Return
>> + *        The number of bytes written to the buffer, or a negative error
>> + *        in case of failure.
>>    */
> [...]
>>       default:
>>           return NULL;
>>       }
>> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
>> index 10672ebc63b7..ea8358b0c748 100644
>> --- a/kernel/trace/bpf_trace.c
>> +++ b/kernel/trace/bpf_trace.c
>> @@ -398,7 +398,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
>>       .arg2_type    = ARG_CONST_SIZE,
>>   };
>>   -const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>> +static void __set_printk_clr_event(void)
>>   {
>>       /*
>>        * This program might be calling bpf_trace_printk,
>> @@ -410,10 +410,58 @@ const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>>        */
>>       if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
>>           pr_warn_ratelimited("could not enable bpf_trace_printk events");
>> +}
>>   +const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>> +{
>> +    __set_printk_clr_event();
>>       return &bpf_trace_printk_proto;
>>   }
>>   +BPF_CALL_4(bpf_trace_vprintk, char *, fmt, u32, fmt_size, const void *, data,
>> +       u32, data_len)
>> +{
>> +    static char buf[BPF_TRACE_PRINTK_SIZE];
>> +    unsigned long flags;
>> +    int ret, num_args;
>> +    u32 *bin_args;
>> +
>> +    if (data_len & 7 || data_len > MAX_BPRINTF_VARARGS * 8 ||
>> +        (data_len && !data))
>> +        return -EINVAL;
>> +    num_args = data_len / 8;
>> +
>> +    ret = bpf_bprintf_prepare(fmt, fmt_size, data, &bin_args, num_args);
>> +    if (ret < 0)
>> +        return ret;
> 
> Given you have ARG_PTR_TO_MEM_OR_NULL for data, does this gracefully handle the
> case where you pass in fmt string containing e.g. %ps but data being NULL? From
> reading bpf_bprintf_prepare() looks like it does just fine, but might be nice
> to explicitly add a tiny selftest case for it while you're at it.
> 
>> +    raw_spin_lock_irqsave(&trace_printk_lock, flags);
>> +    ret = bstr_printf(buf, sizeof(buf), fmt, bin_args);
>> +
>> +    trace_bpf_trace_printk(buf);
>> +    raw_spin_unlock_irqrestore(&trace_printk_lock, flags);
>> +
>> +    bpf_bprintf_cleanup();
>> +
>> +    return ret;
>> +}
> 
> Thanks,
> Daniel