[PATCH v2 bpf-next 0/6] bpf: implement variadic printk helper

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


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 (6):
  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
  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                   | 45 ++++++++++---
 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, 228 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

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 <redacted>
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 4e8540716187..5ce19b376ef7 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 cbc73c08c4a4..2cf4bfa1ab7b 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

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 <redacted>
---
 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 c4f7892edb2b..33414cbeda53 100644
--- a/include/uapi/linux/bpf.h
+++ b/include/uapi/linux/bpf.h

@@ -4871,6 +4871,14 @@ union bpf_attr {
  * 	Return
  *		Value specified by user at BPF link creation/attachment time
  *		or 0, if it was not specified.
+ *
+ * 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),			\

@@ -5048,6 +5056,7 @@ union bpf_attr {
 	FN(timer_cancel),		\
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
+	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 91f24c7b38a1..a137c550046c 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 5ce19b376ef7..863e5ee68558 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c

@@ -1419,6 +1419,8 @@ bpf_base_func_proto(enum bpf_func_id func_id)
 		return &bpf_snprintf_btf_proto;
 	case BPF_FUNC_snprintf:
 		return &bpf_snprintf_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 2cf4bfa1ab7b..83df67f739d6 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)
 {

@@ -1113,6 +1161,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 c4f7892edb2b..33414cbeda53 100644
--- a/tools/include/uapi/linux/bpf.h
+++ b/tools/include/uapi/linux/bpf.h

@@ -4871,6 +4871,14 @@ union bpf_attr {
  * 	Return
  *		Value specified by user at BPF link creation/attachment time
  *		or 0, if it was not specified.
+ *
+ * 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),			\

@@ -5048,6 +5056,7 @@ union bpf_attr {
 	FN(timer_cancel),		\
 	FN(get_func_ip),		\
 	FN(get_attach_cookie),		\
+	FN(trace_vprintk),		\
 	/* */
 
 /* integer value in 'imm' field of BPF_CALL instruction selects which helper

-- 
2.30.2

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. On my system, using a clang built from
recent upstream sources (14.0.0 https://github.com/llvm/llvm-project.git
50b62731452cb83979bbf3c06e828d26a4698dca), attempting to use 4 args to
__bpf_printk (old impl) results in a compile-time error:

  progs/trace_printk.c:21:21: error: too many args to 0x6cdf4b8: i64 = Constant<6>
        trace_printk_ret = __bpf_printk("testing,testing %d %d %d %d\n",

I was able to replicate this behavior with an older clang as well. When
the format string has >3 format specifiers, there is no output to the
trace_pipe in either case.

After this patch, using bpf_printk with 4 args would result in a
trace_vprintk helper call being emitted and a load-time failure on older
kernels.

Signed-off-by: Dave Marchevsky <redacted>
---
 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

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 <redacted>
---
 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 2a58b7b5aea4..af5e7a1e9a7c 100644
--- a/tools/testing/selftests/bpf/Makefile
+++ b/tools/testing/selftests/bpf/Makefile

@@ -313,7 +313,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

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

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

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] wrote:

It needs a rebase.

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] 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. On my system, using a clang built from
recent upstream sources (14.0.0 https://github.com/llvm/llvm-project.git
50b62731452cb83979bbf3c06e828d26a4698dca), attempting to use 4 args to
__bpf_printk (old impl) results in a compile-time error:

  progs/trace_printk.c:21:21: error: too many args to 0x6cdf4b8: i64 = Constant<6>
        trace_printk_ret = __bpf_printk("testing,testing %d %d %d %d\n",

and with a new bpf_printk it will compile to use bpf_trace_vprintk
and gets rejected during load on old kernels, right?
That will be the case for any clang.
It's fine.
Would be good to clarify the commit log.

I was able to replicate this behavior with an older clang as well. When
the format string has >3 format specifiers, there is no output to the
trace_pipe in either case.

I don't understand this paragraph. What are the cases?

After this patch, using bpf_printk with 4 args would result in a
trace_vprintk helper call being emitted and a load-time failure on older
kernels.

right.

+#define __bpf_printk(fmt, ...)                         \
+({                                                     \
+       char ____fmt[] = fmt;                           \

Andrii was suggesting to make it const while we're at it,
but that could be done in a follow up.

On 8/25/21 9:01 PM, Alexei Starovoitov wrote:   

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] wrote:

quoted

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. On my system, using a clang built from
recent upstream sources (14.0.0 https://github.com/llvm/llvm-project.git
50b62731452cb83979bbf3c06e828d26a4698dca), attempting to use 4 args to
__bpf_printk (old impl) results in a compile-time error:

  progs/trace_printk.c:21:21: error: too many args to 0x6cdf4b8: i64 = Constant<6>
        trace_printk_ret = __bpf_printk("testing,testing %d %d %d %d\n",

and with a new bpf_printk it will compile to use bpf_trace_vprintk
and gets rejected during load on old kernels, right?
That will be the case for any clang.
It's fine.
Would be good to clarify the commit log.

Yep, I think we're on the same page here. Wanted to call out the 
changed behavior in case it felt more like 'breaking user expectations'.
Will simplify the commit message for this patch in v3.

quoted

I was able to replicate this behavior with an older clang as well. When
the format string has >3 format specifiers, there is no output to the
trace_pipe in either case.

I don't understand this paragraph. What are the cases?

This was me trying to enumerate behavior before/after this patch in
order to answer the 'does this break user expectations' question. I was
curious whether clang version affected error messages users would see
when doing things old bpf_printk didn't support (>3 args, >3 format
specifiers). Format specifier >3 case is intentional runtime behavior,
so in retrospect there was no reason to focus on clang version there.

Will remove from commit msg.

quoted

After this patch, using bpf_printk with 4 args would result in a
trace_vprintk helper call being emitted and a load-time failure on older
kernels.

right.

quoted

+#define __bpf_printk(fmt, ...)                         \
+({                                                     \
+       char ____fmt[] = fmt;                           \

Andrii was suggesting to make it const while we're at it,
but that could be done in a follow up.

This was intentionally left out of v2 as I wanted to get early feedback
on the macro stuff, will add a patch doing this to v3. 

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] wrote:

nit: is this really misaligned or it's just Gmail's rendering?

+})
+
+#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)

There is no best solution with macros, but I think this one is
extremely error prone because __bpf_nth invocation is very long and
it's hard to even see where printk turns into vprintk.

How about doing it similarly to ___empty in bpf_core_read.h? It will
be something like this (untested and not even compiled, just a demo)

#define __bpf_printk_kind(...) ___bpf_nth(_, ##__VA_ARGS__, new, new,
new, new, new, <however many>, new, old /*3*/, old /*2*/, old /*1*/,
old /*0*/)

#define bpf_printk(fmt, args...) ___bpf_apply(___bpf_printk_,
___bpf_narg(args))(fmt, args)


And you'll have s/__bpf_printk/__bpf_printk_old/ (using
bpf_trace_printk) and s/__bpf_printk_new/__bpf_vprintk/ (using
bpf_trace_vprintk).

This new/old distinction makes it a bit clearer to me. I find
__bpf_nth so counterintuitive that I try not to use it directly
anywhere at all.

+
+#define bpf_printk(fmt, args...)               \
+({                                             \
+       ___bpf_pick_printk(args)(fmt, args);    \
+})

not sure ({ }) buys you anything?...

+
 #endif
--
2.30.2

On 8/30/21 7:55 PM, Andrii Nakryiko wrote:   

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] wrote:

quoted

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. On my system, using a clang built from
recent upstream sources (14.0.0 https://github.com/llvm/llvm-project.git
50b62731452cb83979bbf3c06e828d26a4698dca), attempting to use 4 args to
__bpf_printk (old impl) results in a compile-time error:

  progs/trace_printk.c:21:21: error: too many args to 0x6cdf4b8: i64 = Constant<6>
        trace_printk_ret = __bpf_printk("testing,testing %d %d %d %d\n",

I was able to replicate this behavior with an older clang as well. When
the format string has >3 format specifiers, there is no output to the
trace_pipe in either case.

After this patch, using bpf_printk with 4 args would result in a
trace_vprintk helper call being emitted and a load-time failure on older
kernels.

Signed-off-by: Dave Marchevsky <redacted>
---
 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));               \

nit: is this really misaligned or it's just Gmail's rendering?

It's misaligned, will fix. As is __bpf_pick_printk below.

quoted

+})
+
+#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)

There is no best solution with macros, but I think this one is
extremely error prone because __bpf_nth invocation is very long and
it's hard to even see where printk turns into vprintk.

How about doing it similarly to ___empty in bpf_core_read.h? It will
be something like this (untested and not even compiled, just a demo)

#define __bpf_printk_kind(...) ___bpf_nth(_, ##__VA_ARGS__, new, new,
new, new, new, <however many>, new, old /*3*/, old /*2*/, old /*1*/,
old /*0*/)

#define bpf_printk(fmt, args...) ___bpf_apply(___bpf_printk_,
___bpf_narg(args))(fmt, args)


And you'll have s/__bpf_printk/__bpf_printk_old/ (using
bpf_trace_printk) and s/__bpf_printk_new/__bpf_vprintk/ (using
bpf_trace_vprintk).

This new/old distinction makes it a bit clearer to me. I find
__bpf_nth so counterintuitive that I try not to use it directly
anywhere at all.

When you're saying 'error prone' here, do you mean something like 
'hard to understand and modify'? Asking because IMO adding 
___bpf_apply here makes it harder to understand. Having the full
helper macros in ___bpf_nth makes it obvious that they're being used
somehow.

But I feel more strongly that these should not be renamed to __bpf_printk_{old,new}.
Although this is admittedly an edge case, I'd like to leave an 'escape
hatch' for power users who might not want bpf_printk to change the 
helper call underneath them - they could use the __bpf_{v}printk
macros directly. Of course they could do the same with _{old,new},
but the rename obscures the name of the underlying helper called,
which is the very thing the hypothetical power user cares about in 
this scenario.

One concrete example of such a user: someone who keeps up with
latest bpf developments but needs to run their programs on a fleet
which has some % of older kernels. Using __bpf_printk directly to 
force a compile error for >3 fmt args instead of being bitten at
load time would be desireable.

Also, 'new' name leaves open possibility that something newer comes
along in the future and turns 'new' into 'old', which feels churny. 
Although if these are never used directly it doesn't matter.

I agree with 'it's hard to even see where printk turns into vprintk'
and like your comment idea. If you're fine with keeping names as-is,
will still add /*3*/ /*2*/... and perhaps a /*BOUNDARY*/ marking the
switch from vprintk to printk.

quoted

+
+#define bpf_printk(fmt, args...)               \
+({                                             \
+       ___bpf_pick_printk(args)(fmt, args);    \
+})

not sure ({ }) buys you anything?...

Agreed, will fix.

quoted

+
 #endif
--
2.30.2

On Wed, Sep 1, 2021 at 4:29 PM Dave Marchevsky [off-list ref] wrote:

On 8/30/21 7:55 PM, Andrii Nakryiko wrote:

quoted

On Wed, Aug 25, 2021 at 12:58 PM Dave Marchevsky [off-list ref] wrote:

quoted

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. On my system, using a clang built from
recent upstream sources (14.0.0 https://github.com/llvm/llvm-project.git
50b62731452cb83979bbf3c06e828d26a4698dca), attempting to use 4 args to
__bpf_printk (old impl) results in a compile-time error:

  progs/trace_printk.c:21:21: error: too many args to 0x6cdf4b8: i64 = Constant<6>
        trace_printk_ret = __bpf_printk("testing,testing %d %d %d %d\n",

I was able to replicate this behavior with an older clang as well. When
the format string has >3 format specifiers, there is no output to the
trace_pipe in either case.

After this patch, using bpf_printk with 4 args would result in a
trace_vprintk helper call being emitted and a load-time failure on older
kernels.

Signed-off-by: Dave Marchevsky <redacted>
---
 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));               \

nit: is this really misaligned or it's just Gmail's rendering?

It's misaligned, will fix. As is __bpf_pick_printk below.

quoted

quoted

+})
+
+#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)

There is no best solution with macros, but I think this one is
extremely error prone because __bpf_nth invocation is very long and
it's hard to even see where printk turns into vprintk.

How about doing it similarly to ___empty in bpf_core_read.h? It will
be something like this (untested and not even compiled, just a demo)

#define __bpf_printk_kind(...) ___bpf_nth(_, ##__VA_ARGS__, new, new,
new, new, new, <however many>, new, old /*3*/, old /*2*/, old /*1*/,
old /*0*/)

#define bpf_printk(fmt, args...) ___bpf_apply(___bpf_printk_,
___bpf_narg(args))(fmt, args)


And you'll have s/__bpf_printk/__bpf_printk_old/ (using
bpf_trace_printk) and s/__bpf_printk_new/__bpf_vprintk/ (using
bpf_trace_vprintk).

This new/old distinction makes it a bit clearer to me. I find
__bpf_nth so counterintuitive that I try not to use it directly
anywhere at all.

When you're saying 'error prone' here, do you mean something like
'hard to understand and modify'? Asking because IMO adding
___bpf_apply here makes it harder to understand. Having the full
helper macros in ___bpf_nth makes it obvious that they're being used
somehow.

Hm... I disagree on ___bpf_nth being easier, because of both *reverse*
and *positional* notation. But whichever you prefer, not a big deal.
In this particular case it takes lots of attention to even see at
which position __bpf_vprintk switches to __bpf_printk. They are too
similar and not both verbose and not distinctive enough, IMO.

bpf_apply feels more natural, but I'm the one who wrote a bunch of
bpf_core_read.h macro using that approach, so I'm totally biased.
(Though I wrote and used bpf__nth as well, yet I still hate it, but
it's just a necessary evil).

But I feel more strongly that these should not be renamed to __bpf_printk_{old,new}.
Although this is admittedly an edge case, I'd like to leave an 'escape
hatch' for power users who might not want bpf_printk to change the
helper call underneath them - they could use the __bpf_{v}printk
macros directly. Of course they could do the same with _{old,new},
but the rename obscures the name of the underlying helper called,
which is the very thing the hypothetical power user cares about in
this scenario.

Any of the __ prefixed macro should not be used by anyone and are not
considered part of the API. We can rename, remove, break them at any
time. So regardless of the above, one should not use __bpf_vprintk or
__bpf_vprintk directly in their BPF apps.

One concrete example of such a user: someone who keeps up with
latest bpf developments but needs to run their programs on a fleet
which has some % of older kernels. Using __bpf_printk directly to
force a compile error for >3 fmt args instead of being bitten at
load time would be desireable.

it's not hard for such users to just copy/paste (and actually have
cleaner name). __bpf_printk() is not a hard macro that needs to be
reused by end users.

Also, 'new' name leaves open possibility that something newer comes
along in the future and turns 'new' into 'old', which feels churny.
Although if these are never used directly it doesn't matter.

Right, internal implementation details, as far as end users are concerned.

I agree with 'it's hard to even see where printk turns into vprintk'
and like your comment idea. If you're fine with keeping names as-is,
will still add /*3*/ /*2*/... and perhaps a /*BOUNDARY*/ marking the
switch from vprintk to printk.

BOUNDARY is probably an overkill. Positional comments might be nice, try it.

quoted

quoted

+
+#define bpf_printk(fmt, args...)               \
+({                                             \
+       ___bpf_pick_printk(args)(fmt, args);    \
+})

not sure ({ }) buys you anything?...

Agreed, will fix.

quoted

quoted

+
 #endif
--
2.30.2